sbc.gram.sk# sbc.gram.sk#sh log Syslog logging: enabled (0 messages dropped, 3 messages rate-limited, 0 flushes, 0 overruns, xml disabled, filtering disabled) No Active Message Discriminator. No Inactive Message Discriminator. Console logging: level debugging, 20347 messages logged, xml disabled, filtering disabled Monitor logging: level debugging, 6524 messages logged, xml disabled, filtering disabled Buffer logging: level debugging, 20347 messages logged, xml disabled, filtering disabled Exception Logging: size (4096 bytes) Count and timestamp logging messages: disabled Persistent logging: disabled No active filter modules. Trap logging: level debugging, 31110 message lines logged Logging Source-Interface: VRF Name: GigabitEthernet1 TLS Profiles: Log Buffer (2000000 bytes): Sep 5 15:23:54.909: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 10 to index 11136 Sep 5 15:23:54.909: //-1/xxxxxxxxxxxx/SIP/Info/notify/512/sip_tls_tcp_read_socket: ReadBlock nbytes 16 offset 0 Sep 5 15:23:54.909: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7F108C487B28 with refCount = 1 Sep 5 15:23:54.909: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7F108C4D3AD0 with refCount = 1 Sep 5 15:23:54.909: //-1/xxxxxxxxxxxx/SIP/Info/critical/1024/httpish_msg_process_network_msg: MSG LINE READ FAILURE DUE TO RS->EOF Sep 5 15:23:54.909: //-1/xxxxxxxxxxxx/SIP/Info/critical/1024/ccsip_process_network_message: process_network_msg: not complete Sep 5 15:23:54.909: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7F108C4D3AD0 Sep 5 15:23:54.909: //-1/xxxxxxxxxxxx/SIP/Info/critical/1024/sip_tls_tcp_newmsg_to_spi: process_network_msg: not complete Sep 5 15:23:54.909: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7F108C487B28 Sep 5 15:23:56.492: //-1/xxxxxxxxxxxx/SIP/Info/sipSPITransportConnResetSyslogRateLimit: Releasing memory for node=0x7F10FEADA020 , majorcontext=0x7F10FEADA020, port=53633 Sep 5 15:23:56.504: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 1 to index 2 Sep 5 15:23:56.504: //-1/xxxxxxxxxxxx/SIP/Transport/get_free_conn_entry: Get first free_index: 11137 Sep 5 15:23:56.504: //-1/xxxxxxxxxxxx/SIP/Transport/get_free_conn_entry: Next free_index is 11138 Sep 5 15:23:56.504: //-1/xxxxxxxxxxxx/SIP/Transport/ccsip_add_fd_conn_to_map_tab: Add fd 15 connid 11137 to map table [0x7F108BA4A080] Sep 5 15:23:56.504: //-1/xxxxxxxxxxxx/SIP/Transport/ccsip_add_fd_conn_to_map_tab: After add new entry, print all the entries in map_tab[15]: Sep 5 15:23:56.504: //-1/xxxxxxxxxxxx/SIP/Transport/ccsip_add_fd_conn_to_map_tab: fd is 15, connid is 11137 Sep 5 15:23:56.504: //-1/xxxxxxxxxxxx/SIP/Info/verbose/512/sip_tls_generate_opssl_ctx: Setting default Ciphers and Curves Sep 5 15:23:56.504: //-1/xxxxxxxxxxxx/SIP/Info/verbose/512/sip_tls_generate_opssl_ctx: Turning off TLS session resumption Sep 5 15:23:56.504: //-1/xxxxxxxxxxxx/SIP/Info/info/512/sip_tls_initiate_handshake: Created a child process 238 for TLS handshake Sep 5 15:23:56.504: //-1/xxxxxxxxxxxx/SIP/Info/info/512/sip_tls_initiate_handshake: Socket: 15 handed off to child socket 0 Sep 5 15:23:56.505: //-1/xxxxxxxxxxxx/SIP/Info/info/512/sip_tls_initiate_handshake: SIPSCTX passed to the child process 238 Sep 5 15:23:56.505: //-1/xxxxxxxxxxxx/SIP/Transport/sip_tls_initiate_handshake: Close parent fd 15 Sep 5 15:23:56.505: //-1/xxxxxxxxxxxx/SIP/Info/info/512/sip_tls_tcp_handshake_proc: child proc: Local socket fd 0 Sep 5 15:23:56.505: //-1/xxxxxxxxxxxx/SIP/Transport/sip_tls_tcp_handshake_proc: TLS handshake initiated for new connection - remote_addr=52.114.75.24, remote port=10432, local_address=102.119.228.9, local_port=5061 Sep 5 15:23:56.505: //-1/xxxxxxxxxxxx/SIP/Info/info/512/sip_tls_tcp_handshake_proc: Associated socket 0 in child proc Sep 5 15:23:56.507: //-1/xxxxxxxxxxxx/SIP/Info/info/512/sip_tls_tcp_handshake_proc: Entering HANDSHAKE sip_ctx 0x7F10FE48B0A0 p_index 2B81 Sep 5 15:23:56.898: //-1/xxxxxxxxxxxx/SIP/Transport/sip_tls_tcp_handshake_proc: TLS HANDSHAKE is successful with trunk peer 52.114.75.24 Sep 5 15:23:56.898: //-1/xxxxxxxxxxxx/SIP/Info/info/512/sip_tls_tcp_handshake_proc: Exiting HANDSHAKE sip_ctx 0x7F10FE48B0A0 p_index 2B81 retry_count: 37 Sep 5 15:23:56.898: //-1/xxxxxxxxxxxx/SIP/Info/info/512/sip_tls_tcp_handshake_proc: Socket: 0 handed off to parent socket 15 Sep 5 15:23:56.898: //-1/xxxxxxxxxxxx/SIP/Info/notify/512/sip_tcp_tls_handshake_success: In sip_tcp_tls_handshake_success Sep 5 15:23:56.898: //-1/xxxxxxxxxxxx/SIP/Transport/sip_tcp_tls_handshake_success: TLS handshake success - remote_addr=52.114.75.24, remote_port=10432, local_addr=102.119.228.9, local_port=5061 Sep 5 15:23:56.898: //-1/xxxxxxxxxxxx/SIP/Transport/sip_tcp_tls_handshake_success: Copy the reverse_handoff fd 15 to the original fd 15 in the tls conn tab Sep 5 15:23:56.898: //-1/xxxxxxxxxxxx/SIP/Transport/ccsip_rm_fd_to_conn_from_map_tab: Remove fd 15 connid 11137 from map table [0x7F108BA4A080] Sep 5 15:23:56.898: //-1/xxxxxxxxxxxx/SIP/Transport/ccsip_rm_fd_to_conn_from_map_tab: After remove entry: print all the entries in map_tab[15]: Sep 5 15:23:56.898: //-1/xxxxxxxxxxxx/SIP/Transport/ccsip_add_fd_conn_to_map_tab: Add fd 15 connid 11137 to map table [0x7F108BA4A080] Sep 5 15:23:56.898: //-1/xxxxxxxxxxxx/SIP/Transport/ccsip_add_fd_conn_to_map_tab: After add new entry, print all the entries in map_tab[15]: Sep 5 15:23:56.898: //-1/xxxxxxxxxxxx/SIP/Transport/ccsip_add_fd_conn_to_map_tab: fd is 15, connid is 11137 Sep 5 15:23:56.898: //-1/xxxxxxxxxxxx/SIP/Info/critical/512/sip_tls_tcp_get_local_port: failed to get local address of given socket fd Sep 5 15:23:56.898: //-1/xxxxxxxxxxxx/SIP/Info/verbose/512/sip_tcp_tls_handshake_success: Out sip_tcp_tls_handshake_success Sep 5 15:23:56.898: //-1/xxxxxxxxxxxx/SIP/Transport/sip_tls_tcp_handshake_proc: Helper: Closing child socket fd: 0 Sep 5 15:23:56.899: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 55 Sep 5 15:23:56.899: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Sep 5 15:23:56.899: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x7F10FAD89E08, remote_addr=52.114.75.24, remote_port=10432, local_addr=102.119.228.9, local_port=1392, connid=11137, transport=TLS Over TCP Sep 5 15:23:56.899: //-1/xxxxxxxxxxxx/SIP/Transport/sipCreateConnInstance: Created new accptd conn=0x7F1088641CC8, connid=11137, addr=52.114.75.24, port=10432, local_addr=102.119.228.9, transport=TLS Over TCP, vrfid = 0 Sep 5 15:23:56.930: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 15 to index 11137 Sep 5 15:23:56.930: //-1/xxxxxxxxxxxx/SIP/Info/notify/512/sip_tls_tcp_read_socket: ReadBlock nbytes 1976 offset 0 Sep 5 15:23:56.930: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7F108C2D1620 with refCount = 1 Sep 5 15:23:56.930: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7F10FEC82D88 with refCount = 1 Sep 5 15:23:56.930: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7F108C2D1620 Sep 5 15:23:56.930: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Sep 5 15:23:56.930: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Sep 5 15:23:56.930: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x7F10FAD89E08, remote_addr=52.114.75.24, remote_port=10432, local_addr=102.119.228.9, local_port=5061, connid=11137, transport=TLS Over TCP Sep 5 15:23:56.931: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 10432 connId 11137 Sep 5 15:23:56.931: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: INVITE sip:+421258222888@sbc.gram.sk:5061;user=phone;transport=tls SIP/2.0 FROM: "Lubomir Liska";tag=94e0fc3c03734a71aa6c3b347ec3ba5b TO: CSEQ: 1 INVITE CALL-ID: f6abc9dd0f01521c865331560a0e85b4 MAX-FORWARDS: 70 VIA: SIP/2.0/TLS 52.114.75.24:5061;branch=z9hG4bK11036331 RECORD-ROUTE: CONTACT: CONTENT-LENGTH: 1101 MIN-SE: 300 SUPPORTED: histinfo,timer USER-AGENT: Microsoft.PSTNHub.SIPProxy v.2022.8.27.7 i.EUWE.1 CONTENT-TYPE: application/sdp ALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY SESSION-EXPIRES: 3600 v=0 o=- 103782 0 IN IP4 127.0.0.1 s=session c=IN IP4 52.113.40.28 b=CT:10000000 t=0 0 m=audio 50582 RTP/SAVP 104 9 103 111 18 0 8 97 101 13 118 c=IN IP4 52.113.40.28 a=rtcp:50583 a=ice-ufrag:zegR a=ice-pwd:YrTIpR9JH1Eyv/PSa3MqWGzd a=rtcp-mux a=candidate:1 1 UDP 2130706431 52.113.40.28 50582 typ srflx raddr 10.0.140.144 rport 50582 a=candidate:1 2 UDP 2130705918 52.113.40.28 50583 typ srflx raddr 10.0.140.144 rport 50583 a=candidate:2 1 tcp-act 2121006078 52.113.40.28 49152 typ srflx raddr 10.0.140.144 rport 49152 a=candidate:2 2 tcp-act 2121006078 52.113.40.28 49152 typ srflx raddr 10.0.140.144 rport 49152 a=label:main-audio a=mid:1 a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx a=sendrecv a=rtpmap:104 SILK/16000 a=rtpmap:9 G722/8000 a=rtpmap:103 SILK/8000 a=rtpmap:111 SIREN/16000 a=fmtp:111 bitrate=16000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:97 RED/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=rtpmap:118 CN/16000 a=ptime:20 Sep 5 15:23:56.931: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIIpTrustSilentDiscard: sipSPIIpTrustSilentDiscard: called for method [102] Sep 5 15:23:56.931: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x7F10FDAFDF70) with key=[126490] to table Sep 5 15:23:56.931: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init: Sep 5 15:23:56.931: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init: Sep 5 15:23:56.931: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised.. Sep 5 15:23:56.931: //-1/000000000000/SIP/Info/verbose/4097/ccsip_platform_init_ccb: Initialising rtp session queue Sep 5 15:23:56.931: //-1/xxxxxxxxxxxx/SIP/Info/info/2048/sipSPICheckIpip: VOIP dialpeer (peer=0x55CD6E619E34) found for sip_user: +421258222888 Sep 5 15:23:56.931: //-1/000000000000/SIP/Info/info/2048/sipSPICheckAssertedIdConfig: Dialpeer match is not yet done Sep 5 15:23:56.932: //-1/000000000000/SIP/Info/info/4096/sipSPISetCallingInfo: calling host comes from From: sip.pstnhub.microsoft.com Sep 5 15:23:56.932: //-1/000000000000/SIP/Info/verbose/4096/sipSPIUpdateCallingInfoUsingRpidOrFrom: Updating Calling Info with FROM header data Sep 5 15:23:56.932: //-1/000000000000/SIP/Info/info/2048/sipSPICheckAssertedIdConfig: Dialpeer match is not yet done Sep 5 15:23:56.932: //-1/000000000000/SIP/Info/verbose/1024/sipSPIGetViaHostInURLFormat: VIA URL:sip:52.114.75.24:5061, Host:52.114.75.24 Sep 5 15:23:56.932: //-1/000000000000/SIP/Info/verbose/67584/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: : 421258222156 Sep 5 15:23:56.932: //-1/000000000000/SIP/Info/critical/1024/sipSPIGetFromCalledPartyId: P-Called-Party-ID header not found Sep 5 15:23:56.932: //-1/000000000000/SIP/Info/critical/1024/sipSPIGetPeerByCalledPartyId: P-Called-Party-ID not found or parse error Sep 5 15:23:56.932: //-1/000000000000/SIP/Info/critical/10240/sipSPIGetCallConfig: No match found for P-Called-Party-ID Sep 5 15:23:56.932: //-1/xxxxxxxxxxxx/SIP/Info/verbose/64/ccsip_inbound_profile_populate_callinfo_in_ccb: Dial-peer 0 is used for inbound profiles config Sep 5 15:23:56.932: //-1/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 5 15:23:56.932: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Sep 5 15:23:56.932: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIIpTrustSilentDiscard: sipSPIIpTrustSilentDiscard: called for method [102] Sep 5 15:23:56.932: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPILocateInviteDialogCCB: CCPAI process exist, start processing Sep 5 15:23:56.932: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 52.114.75.24,Port 10432, Transport 4, SentBy Port 5061vrfid 0 Sep 5 15:23:56.933: //-1/000000000000/SIP/Info/verbose/4608/sipSPISipIncomingMsg: copy the natted transport info to ccb natted dest: 52.114.75.24:10432,natted src: 102.119.228.9:5061, natted transport: 4 Sep 5 15:23:56.933: //-1/000000000000/SIP/Info/info/1024/sipSPISipIncomingMsg: sip via host 52.114.75.24 Sep 5 15:23:56.933: //-1/000000000000/SIP/Info/info/9216/sipSPISipIncomingMsg: sip nat auto detect 0 Sep 5 15:23:56.933: //-1/xxxxxxxxxxxx/SIP/Info/verbose/512/ccsip_get_vrf_from_sip_bind: vrfid 0 for tag 0, sip_vrfid 0, voice_vrfid 0 Sep 5 15:23:56.933: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 5 15:23:56.933: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 5 15:23:56.933: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: ip_best_local_address 102.119.228.9 for SIP Sep 5 15:23:56.933: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: bind_inuse: 0conn_reuse: 0 Sep 5 15:23:56.933: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 102.119.228.9 Sep 5 15:23:56.933: //-1/D4515960ACE5/SIP/State/sipSPIChangeState: 0x7F10FDAFDF70 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Sep 5 15:23:56.933: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 52.114.75.24,Port 10432, Transport 4, SentBy Port 5060vrfid 0 Sep 5 15:23:56.933: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone CEDT to SIP default timezone = GMT Sep 5 15:23:56.933: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 52.114.75.24,Port 10432, Transport 4, SentBy Port 5061vrfid 0 Sep 5 15:23:56.933: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x7F10FEC82D88) counter, current msg->refCount = 2 Sep 5 15:23:56.933: //-1/xxxxxxxxxxxx/SIP/Error/httpish_msg_free: Freeing NULL pointer! Sep 5 15:23:56.934: //-1/D4515960ACE5/SIP/Info/verbose/4096/sipSPIAssignCcbLastRequest: Current ccb(0x7F10FDAFDF70)->last_request = 0x7F10FEC82D88, refCount = 2 Sep 5 15:23:56.934: //-1/D4515960ACE5/SIP/Info/info/8192/sipSPIProcessSessionID: SessionID header not present - create uuid Sep 5 15:23:56.934: //-1/D4515960ACE5/SIP/Info/info/8192/sipSPIGenerateSessionUUID: Generate uuid Sep 5 15:23:56.934: //-1/D4515960ACE5/SIP/Info/info/8192/sipSPIGenerateSessionUUID: Initial Invite SIP-TDM /MF case Sep 5 15:23:56.934: //-1/D4515960ACE5/SIP/Info/info/8192/sipSPIGenerateSessionUUID: generated uuid - cc6fec3b3d7a552585eb3a8f9690b579 Sep 5 15:23:56.934: //-1/D4515960ACE5/SIP/Info/notify/8192/sipSPI_Add_SessionIDtoTDContainer: localUUID - cc6fec3b3d7a552585eb3a8f9690b579remoteUUID - 00000000000000000000000000000000 Sep 5 15:23:56.934: //-1/xxxxxxxxxxxx/SIP/Info/info/2048/sipSPICheckIpip: VOIP dialpeer (peer=0x55CD6E619E34) found for sip_user: +421258222888 Sep 5 15:23:56.934: //-1/D4515960ACE5/SIP/Info/info/2048/sipSPICheckAssertedIdConfig: Dialpeer match is not yet done Sep 5 15:23:56.934: //-1/D4515960ACE5/SIP/Info/info/4096/sipSPISetCallingInfo: calling host comes from From: sip.pstnhub.microsoft.com Sep 5 15:23:56.934: //-1/D4515960ACE5/SIP/Info/verbose/4096/sipSPIUpdateCallingInfoUsingRpidOrFrom: Updating Calling Info with FROM header data Sep 5 15:23:56.934: //-1/D4515960ACE5/SIP/Info/info/2048/sipSPICheckAssertedIdConfig: Dialpeer match is not yet done Sep 5 15:23:56.934: //-1/xxxxxxxxxxxx/SIP/Info/critical/4096/sipSPIGetContentGTD: No GTD found in inbound container Sep 5 15:23:56.934: //-1/xxxxxxxxxxxx/SIP/Info/critical/4096/sipSPIGetContentCSTA: No CSTA found in inbound container Sep 5 15:23:56.934: //-1/D4515960ACE5/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x7F10FDAFDF70 key=f6abc9dd0f01521c865331560a0e85b4421258222888 balance 1 Sep 5 15:23:56.934: //-1/D4515960ACE5/SIP/Info/info/8192/sipSPIMatchSrcIpGroup: Match not found on carrier id Sep 5 15:23:56.935: //-1/D4515960ACE5/SIP/Info/critical/8192/sipSPIMatchSrcIpGroup: Match not found on Incoming called number: +421258222888 Sep 5 15:23:56.935: //-1/D4515960ACE5/SIP/Info/critical/8192/sipSPIMatchSrcIpGroup: Match not found on destination pattern: 421258222156 Sep 5 15:23:56.935: //-1/D4515960ACE5/SIP/Info/info/12288/ccsipUpdateIncomingCallParams: ccCallInfo: Calling name Lubomir Liska, number 421258222156, Calling oct3 0x00, oct_3a 0x80, Called number +421258222888 Sep 5 15:23:56.935: //-1/D4515960ACE5/SIP/Info/verbose/1024/sipSPIGetViaHostInURLFormat: VIA URL:sip:52.114.75.24:5061, Host:52.114.75.24 Sep 5 15:23:56.935: //-1/D4515960ACE5/SIP/Info/verbose/67584/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: : 421258222156 Sep 5 15:23:56.935: //-1/D4515960ACE5/SIP/Info/critical/1024/sipSPIGetFromCalledPartyId: P-Called-Party-ID header not found Sep 5 15:23:56.935: //-1/D4515960ACE5/SIP/Info/critical/1024/sipSPIGetPeerByCalledPartyId: P-Called-Party-ID not found or parse error Sep 5 15:23:56.935: //-1/D4515960ACE5/SIP/Info/critical/10240/sipSPIGetCallConfig: No match found for P-Called-Party-ID Sep 5 15:23:56.935: //-1/D4515960ACE5/SIP/Info/info/2048/sipSPISetAudioForcedConfig: audio forced config is set to FALSE Sep 5 15:23:56.935: //-1/D4515960ACE5/SIP/Info/verbose/1024/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header Sep 5 15:23:56.935: //-1/D4515960ACE5/SIP/Info/verbose/2048/sipSPIGetCallConfig: Media Antitrombone disabled Sep 5 15:23:56.935: //-1/D4515960ACE5/SIP/Info/info/8192/sipSPISetMediaFlowMode: Storing the configured mode as FLOW-THROUGH Sep 5 15:23:56.935: //-1/D4515960ACE5/SIP/Info/info/2304/sipSPISetMediaFlowMode: xcoder high-density disabled Sep 5 15:23:56.935: //-1/D4515960ACE5/SIP/Info/info/8192/sipSPISetMediaFlowMode: Flow Mode set to FLOW_THROUGH Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Info/info/8704/sipSPIGetCallConfig: Incoming: No Defer BYE for last call stats Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Info/info/10240/sipSPIGetCallConfig: Non dial peer leg - using RTP Supported Codecs Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 18 Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 0 Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 8 Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 9 Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 4 Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 2 Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 15 Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 3 Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Info/critical/32768/ccsip_ipip_media_forking_update_preferred_codec: MF: Not a Forked SIP leg.. Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Error/ccsip_ipip_media_forking_anchor_leg_config: MF: Dial-peer is absent.. Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Error/ccsip_ipip_media_forking_intra_frame_request_config: MF:video profile Dial-peer is absent.. Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Info/verbose/1/ccsip_set_srtp_config: No Srtp configure for this leg. Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Info/verbose/12288/sipSPIGetModemInfoPerCall: peer_callID=0 Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Info/verbose/8192/sipSPICheckFAAnatAssymetricOrDO2EO: Not a SIP-SIP call or not in FA mode Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Info/info/2049/populate_vcc_data: Non dial peer leg - using RTP Supported Codecs Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 18 Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 0 Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 8 Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 9 Sep 5 15:23:56.936: //-1/D4515960ACE5/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 4 Sep 5 15:23:56.937: //-1/D4515960ACE5/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 2 Sep 5 15:23:56.937: //-1/D4515960ACE5/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 15 Sep 5 15:23:56.937: //-1/D4515960ACE5/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 3 Sep 5 15:23:56.937: //-1/D4515960ACE5/SIP/Info/notify/8192/sipSPISetOverlapConfiguration: Overlap signaling: FALSE: Endpt: SIP Trunk Sep 5 15:23:56.937: //-1/D4515960ACE5/SIP/Info/verbose/10240/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:3 tag:290 Sep 5 15:23:56.937: //-1/D4515960ACE5/SIP/Info/verbose/2048/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0 Sep 5 15:23:56.937: //-1/D4515960ACE5/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 5 15:23:56.937: //-1/D4515960ACE5/SIP/Info/info/10240/sipSPI_ipip_build_consolidated_header_list: Adding passthru related headers Sep 5 15:23:56.937: //-1/D4515960ACE5/SIP/Info/verbose/8192/sipSPI_ipip_find_and_add_hdr_to_queue: Hdr Referred-By does not exist, adding it Sep 5 15:23:56.937: //-1/D4515960ACE5/SIP/Info/info/4096/sipSPIContinueNewMsgInvite: Calling name Lubomir Liska, number 421258222156, Calling oct3 0x00, oct_3a 0x80, ext_priv 0x00, Called number +421258222888, oct3 0x00 Sep 5 15:23:56.937: //-1/D4515960ACE5/SIP/Info/info/4096/sipSPIContinueNewMsgInvite: Carrier id code , prev_cid NONE, next_cid NONE, prev_tgrp NONE, next_tgrp NONE Sep 5 15:23:56.937: //-1/D4515960ACE5/SIP/Info/critical/10240/sipSPIValidateRequestUri: Not Enabled Sep 5 15:23:56.937: //-1/D4515960ACE5/SIP/Info/info/131072/sipSPIRscmsmAvail: Value returned by check is = 0 Sep 5 15:23:56.937: //126125/D4515960ACE5/SIP/Info/critical/4096/sipSPICheckOutBoundDpProvisioning: Cannot obtain the the header bitmap Sep 5 15:23:56.937: //126125/D4515960ACE5/SIP/Info/critical/8192/sipSPI_ipip_IsSDPPassthruEnabled: - 0 Sep 5 15:23:56.937: //126125/D4515960ACE5/SIP/Info/info/8192/sipSPIProcessSessionID: SessionID header not present - create uuid Sep 5 15:23:56.937: //126125/D4515960ACE5/SIP/Info/info/8192/sipSPIGenerateSessionUUID: Generate uuid Sep 5 15:23:56.937: //126125/D4515960ACE5/SIP/Info/info/8192/sipSPIGenerateSessionUUID: Initial Invite SIP-TDM /MF case Sep 5 15:23:56.938: //126125/D4515960ACE5/SIP/Info/info/8192/sipSPIGenerateSessionUUID: generated uuid - 27025b46756c52c4947e5985209289d3 Sep 5 15:23:56.938: //126125/D4515960ACE5/SIP/Info/notify/8192/sipSPI_Add_SessionIDtoTDContainer: localUUID - 27025b46756c52c4947e5985209289d3remoteUUID - 00000000000000000000000000000000 Sep 5 15:23:56.938: //-1/xxxxxxxxxxxx/SIP/Info/info/32768/ccsip_voip_trace_update_peer_sessionId: Cover Buffer:32, Updating peer Session-ID:27025b46756c52c4947e5985209289d3 Sep 5 15:23:56.938: //126125/D4515960ACE5/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_REQ Sep 5 15:23:56.938: //126125/D4515960ACE5/SIP/Event/Session-Timer/sipSTSLMain: dir:2, method:102, resp_code:0, container:7F10FEAD5288 Sep 5 15:23:56.938: //126125/D4515960ACE5/SIP/Info/info/8192/Session-Timer/sipSTSLExtractSessionExpiresHdr: Session-Expires value: 3600 refresher: none Sep 5 15:23:56.938: //126125/D4515960ACE5/SIP/Info/info/8192/Session-Timer/sipSTSLExtractMinSEHdr: Min-SE Duration: 300 Sep 5 15:23:56.938: //126125/D4515960ACE5/SIP/Info/info/8192/Session-Timer/sipSTSLGetInternalSREvent: E_STSL_INITIAL_SR_REQ Sep 5 15:23:56.938: //126125/D4515960ACE5/SIP/Info/verbose/8192/Session-Timer/sipSTSLInitialSRReqPeerEventGen: sending received session expires to the peer leg Sep 5 15:23:56.938: //126125/D4515960ACE5/SIP/Event/Session-Timer/sipSTSLPrintTDContainer: Peer-Event: E_STSL_PASS_ST_PARAMS, SE Value:3600, SE Refresher:none, Min-SE Value:1800, flags:2011 Sep 5 15:23:56.938: //126125/D4515960ACE5/SIP/Info/info/8192/Session-Timer/sipSTSLMain: SE: 3600;refresher:none peer refresher:none, flags:2011, posted event:E_STSL_INVALID_PEER_EVENT, reason:4 Configured SE:1800, Configured Min-SE:1800 Sep 5 15:23:56.938: //126125/D4515960ACE5/SIP/Info/critical/1024/sipSPIProcessHistoryInfoHeader: No HI headers recvd from app container Sep 5 15:23:56.938: //126125/D4515960ACE5/SIP/Info/critical/1024/sipSPIProcessDiversionHeader: No diversion headers recvd from app container Sep 5 15:23:56.938: //126125/D4515960ACE5/SIP/Info/critical/16384/sipSPIProcessReplacesHeader: No replaces hdr found Sep 5 15:23:56.938: //-1/xxxxxxxxxxxx/SIP/Info/verbose/1024/sipSPIGetContentCPA: No CPA found in inbound container Sep 5 15:23:56.938: //126125/D4515960ACE5/SIP/Info/verbose/1024/sipSPIProcessCPA: No x-cisco-cpa content found SIP: Warning: Transport protocol type unsupported (tcp-act). SIP: Warning: Transport protocol type unsupported (tcp-act). Sep 5 15:23:56.939: //126125/D4515960ACE5/SIP/Info/verbose/1/sipSPIDoMediaNegotiation: Number of m-lines = 1 Sep 5 15:23:56.939: //126125/D4515960ACE5/SIP/Info/verbose/1/sipSPIValidateConnectionAddress: Dest port = 50582 Sep 5 15:23:56.939: //126125/D4515960ACE5/SIP/Info/notify/6/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Sep 5 15:23:56.939: //126125/D4515960ACE5/SIP/Info/verbose/513/resolve_media_ip_address_to_bind: peer_tag=0 Sep 5 15:23:56.939: //126125/D4515960ACE5/SIP/Info/info/2048/resolve_media_ip_address_to_bind: Configuration not found for bind media source-ip Sep 5 15:23:56.939: //-1/xxxxxxxxxxxx/SIP/Info/verbose/512/ccsip_get_vrf_from_sip_bind: vrfid 0 for tag 0, sip_vrfid 0, voice_vrfid 0 Sep 5 15:23:56.939: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_media_ip_address_to_bind: VRF id = 0 Sep 5 15:23:56.939: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_media_ip_address_to_bind: ip_best_local_address 102.119.228.9 for SIP Sep 5 15:23:56.939: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_media_ip_address_to_bind: return addr 102.119.228.9 Sep 5 15:23:56.939: //126125/D4515960ACE5/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 102.119.228.9 Sep 5 15:23:56.939: //126125/D4515960ACE5/SIP/Info/verbose/1/sipSPI_detect_media_loop: Number of media loops detected - 0 Sep 5 15:23:56.939: //126125/D4515960ACE5/SIP/Info/info/17/sipIfSRTPAllowed: accepting SRTP with unsecure signaling, url type = 1 SIP: (126125) Group (a= group line) attribute, level 65535 instance 1 not found. Sep 5 15:23:56.939: //126125/D4515960ACE5/SIP/Error/sipSPIDoMediaNegotiation: Failed to negotiate main stream. Main stream dead Sep 5 15:23:56.939: //126125/D4515960ACE5/SIP/Error/sipSPIHandleInviteMedia: Media Negotiation failed for an incoming call Sep 5 15:23:56.939: //126125/D4515960ACE5/SIP/Info/critical/4096/ccsip_set_cc_cause_for_spi_err: Categorized cause:65, category:278 Sep 5 15:23:56.939: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_set_release_source_for_peer: ownCallId[126125], src[6] Sep 5 15:23:56.940: //-1/xxxxxxxxxxxx/SIP/Info/info/32768/ccsip_voip_trace_iec_mark: No CCB. Call will not be marked for Voip Trace. Sep 5 15:23:56.940: //-1/xxxxxxxxxxxx/SIP/Info/info/32768/symp_mark_voip_trace_instance: Marked for Voip Trace. buffer Id:32 Sep 5 15:23:56.940: //126125/D4515960ACE5/SIP/Info/info/32768/ccsip_mark_voip_trace: Marked the call for VOIP Trace - Error Index Sep 5 15:23:56.940: //126125/D4515960ACE5/SIP/Info/info/4096/sipSPIContinueNewMsgInvite: ccsip_api_call_setup_ind returned: SIP_UNACCEPTABLE_MEDIA_ERR Sep 5 15:23:56.940: //126125/D4515960ACE5/SIP/Error/sipSPIContinueNewMsgInvite: Unacceptable media indicated for INVITE Sep 5 15:23:56.940: //126125/D4515960ACE5/SIP/Info/critical/4096/ccsip_set_cc_cause_for_spi_err: Categorized cause:65, category:278 Sep 5 15:23:56.940: //126125/D4515960ACE5/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x7F10FDAFDF70 key=f6abc9dd0f01521c865331560a0e85b42044C6C8-1556 balance 1 Sep 5 15:23:56.940: //126125/D4515960ACE5/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable: Adding call id 1ECAD to table Sep 5 15:23:56.940: //126125/D4515960ACE5/SIP/Info/verbose/4096/sipSPISendInviteResponse: Dialog State: [0] Sep 5 15:23:56.940: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7F10FEAEC170 with refCount = 1 Sep 5 15:23:56.940: //126125/D4515960ACE5/SIP/Info/info/8192/sipSPIGetTDSessionID: Get session-ID local uuid - 27025b46756c52c4947e5985209289d3 remote uuid - 00000000000000000000000000000000 Sep 5 15:23:56.940: //126125/D4515960ACE5/SIP/Info/info/8192/sipSPIGenerateSessionUUID: Generate uuid Sep 5 15:23:56.940: //126125/D4515960ACE5/SIP/Info/info/8192/sipSPIGenerateSessionUUID: generated uuid - 779c2099bfeb596e8a129d04f6a33b91 Sep 5 15:23:56.940: //126125/D4515960ACE5/SIP/Info/notify/8192/sipSPIAddSessionID: localUUID - 779c2099bfeb596e8a129d04f6a33b91 remoteUUID - 27025b46756c52c4947e5985209289d3 Sep 5 15:23:56.940: //126125/D4515960ACE5/SIP/Info/notify/8192/sipSPIAddSessionID: Session-ID header 27025b46756c52c4947e5985209289d3;remote=779c2099bfeb596e8a129d04f6a33b91 Sep 5 15:23:56.940: //126125/D4515960ACE5/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_RESP Sep 5 15:23:56.940: //126125/D4515960ACE5/SIP/Event/Session-Timer/sipSTSLMain: dir:1, method:102, resp_code:488, container:7F10FEAD5490 Sep 5 15:23:56.940: //126125/D4515960ACE5/SIP/Info/info/8192/Session-Timer/sipSTSLMain: SE: 3600;refresher:none peer refresher:none, flags:11, posted event:E_STSL_INVALID_PEER_EVENT, reason:4 Configured SE:1800, Configured Min-SE:1800 Sep 5 15:23:56.941: //126125/D4515960ACE5/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 3 event Sep 5 15:23:56.941: //126125/D4515960ACE5/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container for instance 3, tag 82 Sep 5 15:23:56.941: //126125/D4515960ACE5/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container for instance 3, tag 93 Sep 5 15:23:56.941: //126125/D4515960ACE5/SIP/Info/info/4096/sipSPISendInviteResponse: Associated container=0x7F10FEAD5490 to Invite Response 488 Sep 5 15:23:56.941: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Sep 5 15:23:56.941: //126125/D4515960ACE5/SIP/Transport/sipSPITransportSendMessage: msg=0x7F10FEAEC170, addr=52.114.75.24, port=10432, sentBy_port=5061, local_addr=102.119.228.9, is_req=0, transport=4, switch=0, callBack=0x55CD655E5960 Sep 5 15:23:56.941: //126125/D4515960ACE5/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 5 15:23:56.941: //126125/D4515960ACE5/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 5 15:23:56.941: //126125/D4515960ACE5/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Sep 5 15:23:56.941: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x7F10FEAEC170, addr=52.114.75.24, port=10432, local_addr=102.119.228.9, connId=11137 vrfid=0 sig_tos=0x68 for TLS Sep 5 15:23:56.941: //126125/D4515960ACE5/SIP/Info/critical/512/sentErrResDisconnecting: Sent an 3456XX Error Response Sep 5 15:23:56.941: //126125/D4515960ACE5/SIP/State/sipSPIChangeState: 0x7F10FDAFDF70 : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE) Sep 5 15:23:56.942: //126125/D4515960ACE5/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 488 Not Acceptable Media Via: SIP/2.0/TLS 52.114.75.24:5061;branch=z9hG4bK11036331 From: "Lubomir Liska";tag=94e0fc3c03734a71aa6c3b347ec3ba5b To: ;tag=2044C6C8-1556 Date: Mon, 05 Sep 2022 13:23:56 GMT Call-ID: f6abc9dd0f01521c865331560a0e85b4 CSeq: 1 INVITE Allow-Events: telephone-event Warning: 399 102.119.228.9 "SRTP Offer/Answer not acceptable.RTP configured on dialpeer" Reason: Q.850;cause=65 Server: Cisco-SIPGateway/IOS-17.3.5 Session-ID: 27025b46756c52c4947e5985209289d3;remote=779c2099bfeb596e8a129d04f6a33b91 Content-Length: 0 Sep 5 15:23:56.942: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7F10FEAEC170 Sep 5 15:23:56.972: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 15 to index 11137 Sep 5 15:23:56.972: //-1/xxxxxxxxxxxx/SIP/Info/notify/512/sip_tls_tcp_read_socket: ReadBlock nbytes 542 offset 0 Sep 5 15:23:56.973: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7F10FEAEC170 with refCount = 1 Sep 5 15:23:56.973: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7F10FED944B8 with refCount = 1 Sep 5 15:23:56.973: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7F10FEAEC170 Sep 5 15:23:56.973: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Sep 5 15:23:56.973: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Sep 5 15:23:56.973: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x7F10FAD89E08, remote_addr=52.114.75.24, remote_port=10432, local_addr=102.119.228.9, local_port=5061, connid=11137, transport=TLS Over TCP Sep 5 15:23:56.973: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 10432 connId 11137 Sep 5 15:23:56.973: //126125/D4515960ACE5/SIP/Info/verbose/4096/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x7F10FDAFDF70 Sep 5 15:23:56.973: //126125/D4515960ACE5/SIP/Msg/ccsipDisplayMsg: Received: ACK sip:+421258222888@sbc.gram.sk:5061;user=phone;transport=tls SIP/2.0 FROM: "Lubomir Liska";tag=94e0fc3c03734a71aa6c3b347ec3ba5b TO: ;tag=2044C6C8-1556 CSEQ: 1 ACK CALL-ID: f6abc9dd0f01521c865331560a0e85b4 MAX-FORWARDS: 70 VIA: SIP/2.0/TLS 52.114.75.24:5061;branch=z9hG4bK11036331 CONTENT-LENGTH: 0 USER-AGENT: Microsoft.PSTNHub.SIPProxy v.2022.8.27.7 i.EUWE.1 ALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY Sep 5 15:23:56.973: //126125/D4515960ACE5/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 5 15:23:56.973: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Sep 5 15:23:56.974: //126125/D4515960ACE5/SIP/Info/verbose/4096/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x7F10FDAFDF70 Sep 5 15:23:56.974: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x7F10FED944B8) counter, current msg->refCount = 2 Sep 5 15:23:56.974: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 52.114.75.24,Port 10432, Transport 4, SentBy Port 5060vrfid 0 Sep 5 15:23:56.974: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone CEDT to SIP default timezone = GMT Sep 5 15:23:56.974: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 52.114.75.24,Port 10432, Transport 4, SentBy Port 5061vrfid 0 Sep 5 15:23:56.974: //126125/D4515960ACE5/SIP/Info/info/4096/sipSPISetCallingInfo: calling host comes from From: sip.pstnhub.microsoft.com Sep 5 15:23:56.974: //126125/D4515960ACE5/SIP/Info/verbose/4096/sipSPIUpdateCallingInfoUsingRpidOrFrom: Updating Calling Info with FROM header data Sep 5 15:23:56.974: //126125/D4515960ACE5/SIP/Info/info/4096/sipSPISetCommonTimer: Started generic timer type 2 for 240000 millisecs Sep 5 15:23:56.974: //126125/D4515960ACE5/SIP/Info/verbose/4096/sipSPICallCloseAfterFinalStat: sipSPICallCloseAfterFinalStat: Sep 5 15:23:56.974: //126125/D4515960ACE5/SIP/State/sipSPIChangeState: 0x7F10FDAFDF70 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE) Sep 5 15:23:56.974: //126125/D4515960ACE5/SIP/Call/sipSPICallInfo: The Call Setup Information is: Call Control Block (CCB) : 0x0x7F10FDAFDF70 State of The Call : STATE_DEAD TCP Sockets Used : YES Calling Number : 421258222156 Called Number : +421258222888 Source IP Address (Sig ): 102.119.228.9 Destn SIP Req Addr:Port : 52.114.75.24:0 Destn SIP Resp Addr:Port : 52.114.75.24:10432 Destination Name : 52.114.75.24 Sep 5 15:23:56.974: //126125/D4515960ACE5/SIP/Call/sipSPIMediaCallInfo: Number of Media Streams: 1 Media Stream : 1 Negotiated Codec : No Codec Negotiated Codec Bytes : 0 Nego. Codec payload : 255 (tx), 255 (rx) Negotiated Dtmf-relay : 0 Dtmf-relay Payload : 0 (tx), 0 (rx) Source IP Address (Media): 102.119.228.9 Source IP Port (Media): 0 Destn IP Address (Media): 52.113.40.28 Destn IP Port (Media): 50582 Orig Destn IP Address:Port (Media): [ - ]:0 Sep 5 15:23:56.974: //126125/D4515960ACE5/SIP/Call/sipSPICallInfo: Disconnect Cause (CC) : 65 Disconnect Cause (SIP) : 488 Sep 5 15:23:56.974: //126125/D4515960ACE5/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 1ECAD Sep 5 15:23:56.974: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[126490] removed. Sep 5 15:23:56.974: //126125/D4515960ACE5/SIP/Info/info/4096/sipSPIStopCommonTimer: Stopping Generic Timer 2 Sep 5 15:23:56.974: //126125/D4515960ACE5/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x7F10FDAFDF70 key=f6abc9dd0f01521c865331560a0e85b4421258222888 Sep 5 15:23:56.975: //126125/D4515960ACE5/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x7F10FDAFDF70 key=f6abc9dd0f01521c865331560a0e85b42044C6C8-1556 Sep 5 15:23:56.975: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x7F10FEC82D88) counter, current msg->refCount = 1 Sep 5 15:23:56.975: //126125/D4515960ACE5/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Sep 5 15:23:56.975: //126125/D4515960ACE5/SIP/Error/sipSPIFlushDeferredQueue: Invalid deferredQueue Sep 5 15:23:56.975: //-1/xxxxxxxxxxxx/SIP/Info/info/32768/symp_rem_voip_event_trace_instance: Enqueue bufferId:32 for VOIP Trace dump Sep 5 15:23:56.975: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x7F10FED944B8) counter, current msg->refCount = 1 Sep 5 15:23:56.975: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x7F10FAD89E08, addr=52.114.75.24, port=10432, local_addr=102.119.228.9, unregistering context=0x7F10FDAFDF70 Sep 5 15:23:56.975: //126125/D4515960ACE5/SIP/Transport/sipSPITransportContextCleanup: Could not purge context gcb=0x7F10FDAFDF70 from the connection; gcb might be locked Sep 5 15:23:56.975: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7F10FEC82D88 Sep 5 15:23:56.975: //126125/D4515960ACE5/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Sep 5 15:23:56.975: //126125/D4515960ACE5/SIP/Info/verbose/36864/sipSPI_ipip_free_header_hash_queue: Deleting Header Hash queue Sep 5 15:23:56.975: //126125/D4515960ACE5/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer Sep 5 15:23:56.975: //126125/D4515960ACE5/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x7F10FDAFDF70 Sep 5 15:23:56.975: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[126490] Sep 5 15:23:56.975: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7F10FED944B8 Sep 5 15:23:57.898: //-1/xxxxxxxxxxxx/SIP/Info/info/32768/ccsip_voip_trace_enqueue_event_trace_queue: VOIP Trace Dump for bufferID:32 Sep 5 15:23:57.898: //-1/xxxxxxxxxxxx/SIP/Info/info/32768/ccsip_event_trace_process_event: Dumping traces for cover buffer:32 and updating statistics 1797: Sep 5 13:23:57.898: //126125/D4515960ACE5/ ------------------ Cover Buffer --------------- Search-key = 421258222156:+421258222888:126125 Timestamp = Sep 5 13:23:56.932 CallID = 126125 Peer-CallID = NA Correlator = NA Called-Number = +421258222888 Calling-Number = 421258222156 SIP CallID = f6abc9dd0f01521c865331560a0e85b4 SIP SessionID = GUID = D4515960ACE5 ----------------------------------------------- 1778: Sep 5 13:23:56.932: //126125/D4515960ACE5/CUBE_VT/SIP/Msg/ccsipDisplayMsg: Received: INVITE sip:+421258222888@sbc.gram.sk:5061;user=phone;transport=tls SIP/2.0 FROM: "Lubomir Liska";tag=94e0fc3c03734a71aa6c3b347ec3ba5b TO: CSEQ: 1 INVITE CALL-ID: f6abc9dd0f01521c865331560a0e85b4 MAX-FORWARDS: 70 VIA: SIP/2.0/TLS 52.114.75.24:5061;branch=z9hG4bK11036331 RECORD-ROUTE: CONTACT: CONTENT-LENGTH: 1101 MIN-SE: 300 SUPPORTED: histinfo,timer USER-AGENT: Microsoft.PSTNHub.SIPProxy v.2022.8.27.7 i.EUWE.1 CONTENT-TYPE: application/sdp ALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY SESSION-EXPIRES: 3600 v=0 o=- 103782 0 IN IP4 127.0.0.1 s=session c=IN IP4 52.113.40.28 b=CT:10000000 t=0 0 m=audio 50582 RTP/SAVP 104 9 103 111 18 0 8 97 101 13 118 c=IN IP4 52.113.40.28 a=rtcp:50583 a=ice-ufrag:zegR a=ice-pwd:YrTIpR9JH1Eyv/PSa3MqWGzd a=rtcp-mux a=candidate:1 1 UDP 2130706431 52.113.40.28 50582 typ srflx raddr 10.0.140.144 rport 50582 a=candidate:1 2 UDP 2130705918 52.113.40.28 50583 typ srflx raddr 10.0.140.144 rport 50583 a=candidate:2 1 tcp-act 2121006078 52.113.40.28 49152 typ srflx raddr 10.0.140.144 rport 49152 a=candidate:2 2 tcp-act 2121006078 52.113.40.28 49152 typ srflx raddr 10.0.140.144 rport 49152 a=label:main-audio a=mid:1 a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx a=sendrecv a=rtpmap:104 SILK/16000 a=rtpmap:9 G722/8000 a=rtpmap:103 SILK/8000 a=rtpmap:111 SIREN/16000 a=fmtp:111 bitrate=16000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:97 RED/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=rtpmap:118 CN/16000 a=ptime:20 1782: Sep 5 13:23:56.932: //126125/D4515960ACE5/CUBE_VT/SIP/FSM/SPI-State-Change: Current State = STATE_NONE, Next State = STATE_IDLE, Current Sub-State = STATE_NONE, Next Sub-State = STATE_NONE 1783: Sep 5 13:23:56.934: //126125/D4515960ACE5/CUBE_VT/SIP/MISC/Matched Dialpeer: Dir:Inbound, Peer-Tag: 0 1784: Sep 5 13:23:56.935: //126125/D4515960ACE5/CUBE_VT/SIP/MISC/Error: ccsip_ipip_media_forking_anchor_leg_config: MF: Dial-peer is absent.. 1785: Sep 5 13:23:56.935: //126125/D4515960ACE5/CUBE_VT/SIP/MISC/Error: ccsip_ipip_media_forking_intra_frame_request_config: MF:video profile Dial-peer is absent.. 1786: Sep 5 13:23:56.938: //126125/D4515960ACE5/CUBE_VT/SIP/MISC/Error: sipSPIDoMediaNegotiation: Failed to negotiate main stream. Main stream dead 1787: Sep 5 13:23:56.940: //126125/D4515960ACE5/CUBE_VT/SIP/MISC/Call Disconnect: Initiated at: 0x1700849, Originated at:0x4103C6E, Cause Code = 65 1788: Sep 5 13:23:56.941: //126125/D4515960ACE5/CUBE_VT/SIP/FSM/SPI-State-Change: Current State = STATE_IDLE, Next State = STATE_DISCONNECTING, Current Sub-State = STATE_NONE, Next Sub-State = STATE_NONE 1789: Sep 5 13:23:56.941: //126125/D4515960ACE5/CUBE_VT/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 488 Not Acceptable Media Via: SIP/2.0/TLS 52.114.75.24:5061;branch=z9hG4bK11036331 From: "Lubomir Liska";tag=94e0fc3c03734a71aa6c3b347ec3ba5b To: ;tag=2044C6C8-1556 Date: Mon, 05 Sep 2022 13:23:56 GMT Call-ID: f6abc9dd0f01521c865331560a0e85b4 CSeq: 1 INVITE Allow-Events: telephone-event Warning: 399 102.119.228.9 "SRTP Offer/Answer not acceptable.RTP configured on dialpeer" Reason: Q.850;cause=65 Server: Cisco-SIPGateway/IOS-17.3.5 Session-ID: 27025b46756c52c4947e5985209289d3;remote=779c2099bfeb596e8a129d04f6a33b91 Content-Length: 0 1791: Sep 5 13:23:56.972: //126125/D4515960ACE5/CUBE_VT/SIP/Msg/ccsipDisplayMsg: Received: ACK sip:+421258222888@sbc.gram.sk:5061;user=phone;transport=tls SIP/2.0 FROM: "Lubomir Liska";tag=94e0fc3c03734a71aa6c3b347ec3ba5b TO: ;tag=2044C6C8-1556 CSEQ: 1 ACK CALL-ID: f6abc9dd0f01521c865331560a0e85b4 MAX-FORWARDS: 70 VIA: SIP/2.0/TLS 52.114.75.24:5061;branch=z9hG4bK11036331 CONTENT-LENGTH: 0 USER-AGENT: Microsoft.PSTNHub.SIPProxy v.2022.8.27.7 i.EUWE.1 ALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY 1793: Sep 5 13:23:56.972: //126125/D4515960ACE5/CUBE_VT/SIP/FSM/Event-Action: Event = SIPSPI_EV_NEW_MESSAGE, Current State = STATE_DISCONNECTING 1794: Sep 5 13:23:56.973: //126125/D4515960ACE5/CUBE_VT/SIP/FSM/SPI-State-Change: Current State = STATE_DISCONNECTING, Next State = STATE_DEAD, Current Sub-State = STATE_NONE, Next Sub-State = STATE_NONE 1795: Sep 5 13:23:56.973: //126125/D4515960ACE5/CUBE_VT/SIP/MISC/Error: sipSPIFlushDeferredQueue: Invalid deferredQueue 1796: Sep 5 13:23:56.974: //126125/D4515960ACE5/CUBE_VT/SIP/API: voip_rtp_release_port (0) Sep 5 15:23:57.899: //-1/xxxxxxxxxxxx/SIP/Info/verbose/32768/symp_et_clear_cover_buffer: Entered Sep 5 15:23:57.899: //-1/xxxxxxxxxxxx/SIP/Info/verbose/32768/symp_enlist_display_buffer: Moving to HistoryQ Sep 5 15:23:57.949: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x7F10FDAFDF70) with key=[126491] to table Sep 5 15:23:57.950: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init: Sep 5 15:23:57.950: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init: Sep 5 15:23:57.950: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised.. Sep 5 15:23:57.950: //-1/000000000000/SIP/Info/verbose/4097/ccsip_platform_init_ccb: Initialising rtp session queue Sep 5 15:23:57.950: //-1/xxxxxxxxxxxx/SIP/Info/verbose/512/ccsip_get_vrf_from_sip_bind: vrfid 0 for tag 20, sip_vrfid 0, voice_vrfid 0 Sep 5 15:23:57.950: //126126/000000000000/SIP/Info/verbose/8192/ccsip_send_ood_options_ping: ccsip_send_ood_options_ping: peer_tag = 20, tenant_tag = 100, VRFId = 0 Sep 5 15:23:57.950: //126126/000000000000/SIP/State/sipSPIChangeState: 0x7F10FDAFDF70 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Sep 5 15:23:57.950: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 37 Sep 5 15:23:57.950: //126126/000000000000/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable: Adding call id 1ECAE to table Sep 5 15:23:57.950: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_DNS_RESOLVE Sep 5 15:23:57.950: //126126/000000000000/SIP/State/sipSPIChangeState: 0x7F10FDAFDF70 : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_SENT_DNS) Sep 5 15:23:57.950: //126126/000000000000/SIP/State/sipSPIChangeState: 0x7F10FDAFDF70 : State change from (STATE_IDLE, SUBSTATE_SENT_DNS) to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_SENT_DNS) Sep 5 15:23:57.950: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/sip_dns_type_a_aaaa_query: DNS query for cucm.cucm.sk and type:1 Sep 5 15:23:57.951: //-1/xxxxxxxxxxxx/SIP/Info/notify/8192/sip_dns_type_a_query: TYPE A query successful for cucm.cucm.sk Sep 5 15:23:57.951: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/sip_dns_type_a_query: ttl for A records = 10 seconds Sep 5 15:23:57.951: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/sip_dns_type_a_aaaa_query: IP Address of cucm.cucm.sk is: Sep 5 15:23:57.951: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/sip_dns_type_a_aaaa_query: 172.24.34.71 Sep 5 15:23:57.952: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 43 Sep 5 15:23:57.952: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/sipSPICacheHostToCCB: sipSPICacheHostToCCB dnsResponse.num_hosts = 1 Sep 5 15:23:57.952: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/sipSPICacheHostToCCB: IP Address No. 1, IP address 172.24.34.71 Sep 5 15:23:57.952: //-1/xxxxxxxxxxxx/SIP/Info/verbose/512/ccsip_get_vrf_from_sip_bind: vrfid 0 for tag 20, sip_vrfid 0, voice_vrfid 0 Sep 5 15:23:57.952: //126126/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 5 15:23:57.952: //126126/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 5 15:23:57.952: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 172.24.34.162 for SIP Sep 5 15:23:57.952: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 172.24.34.162 for SIP Sep 5 15:23:57.952: //126126/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 172.24.34.162 Sep 5 15:23:57.952: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: bind_inuse: 1conn_reuse: 0 Sep 5 15:23:57.952: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 172.24.34.162 Sep 5 15:23:57.952: //126126/000000000000/SIP/State/sipSPIChangeState: 0x7F10FDAFDF70 : State change from (SIP_STATE_OPTIONS_WAIT, SUBSTATE_SENT_DNS) to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_NONE) Sep 5 15:23:57.952: //-1/xxxxxxxxxxxx/SIP/Info/verbose/512/ccsip_get_vrf_from_sip_bind: vrfid 0 for tag 20, sip_vrfid 0, voice_vrfid 0 Sep 5 15:23:57.952: //126126/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 5 15:23:57.952: //126126/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 5 15:23:57.952: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 172.24.34.162 for SIP Sep 5 15:23:57.952: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 172.24.34.162 for SIP Sep 5 15:23:57.952: //126126/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 172.24.34.162 Sep 5 15:23:57.952: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: bind_inuse: 1conn_reuse: 0 Sep 5 15:23:57.952: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 172.24.34.162 Sep 5 15:23:57.953: //126126/000000000000/SIP/Info/verbose/4096/sipSPIUaddCcbToUACTable: ****Adding to UAC table.0x7F10FDAFDF70 D4ECD5EA-2C5411ED-ACE98A42-88ABFBF4@sbc.gram.sk Sep 5 15:23:57.953: //126126/000000000000/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x7F10FDAFDF70 key=D4ECD5EA-2C5411ED-ACE98A42-88ABFBF4@sbc.gram.sk balance 1 Sep 5 15:23:57.953: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7F108C485D48 with refCount = 1 Sep 5 15:23:57.953: //126126/000000000000/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 15 event Sep 5 15:23:57.953: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone CEDT to SIP default timezone = GMT Sep 5 15:23:57.953: //126126/000000000000/SIP/Error/sipSPIAddPrivacyHeader: Orig Container is NULL...should have value except in case of sending OOD Options ping. Sep 5 15:23:57.953: //126126/000000000000/SIP/Error/sipSPIAddAssertedIDHeader: Orig Container is NULL...should have value except in case of sending OOD Options ping. Sep 5 15:23:57.953: //126126/000000000000/SIP/Error/sipSPIAddPreferredIDHeader: Orig Container is NULL...should have value except in case of sending OOD Options ping. Sep 5 15:23:57.953: //126126/000000000000/SIP/Info/info/4096/sipSPISendOptionsRequest: Associated container=0x7F10FEADB8E8 to Options Sep 5 15:23:57.953: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Sep 5 15:23:57.953: //-1/xxxxxxxxxxxx/SIP/Info/verbose/512/ccsip_get_vrf_from_sip_bind: vrfid 0 for tag 20, sip_vrfid 0, voice_vrfid 0 Sep 5 15:23:57.953: //126126/000000000000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Dial peer configuration, Switch Transport is FALSE Sep 5 15:23:57.953: //126126/000000000000/SIP/Transport/sipSPITransportSendMessage: msg=0x7F108C485D48, addr=172.24.34.71, port=5061, sentBy_port=0, local_addr=172.24.34.162, is_req=1, transport=4, switch=0, callBack=0x55CD655EC5B0 Sep 5 15:23:57.953: //126126/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 5 15:23:57.953: //126126/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 5 15:23:57.953: //126126/000000000000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Sep 5 15:23:57.953: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:172.24.34.71, rport:5061 with laddr:172.24.34.162 Sep 5 15:23:57.954: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x7F10FDAFDF70 with connection=0x7F10FADC8BE8 context list Sep 5 15:23:57.954: //126126/000000000000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x7F108C485D48 Sep 5 15:23:57.954: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x7F108C485D48, addr=172.24.34.71, port=5061, local_addr=172.24.34.162, connId=4 vrfid=0 sig_tos=0x68 for TLS Sep 5 15:23:57.954: //-1/xxxxxxxxxxxx/SIP/Error/httpish_msg_free: Freeing NULL pointer! Sep 5 15:23:57.954: //126126/000000000000/SIP/Msg/ccsipDisplayMsg: Sent: OPTIONS sip:cucm.cucm.sk:5061 SIP/2.0 Via: SIP/2.0/TLS 172.24.34.162:5061;branch=z9hG4bKF6B84D From: ;tag=2044CABD-21B To: Date: Mon, 05 Sep 2022 13:23:57 GMT Call-ID: D4ECD5EA-2C5411ED-ACE98A42-88ABFBF4@sbc.gram.sk User-Agent: Cisco-SIPGateway/IOS-17.3.5 Max-Forwards: 70 CSeq: 101 OPTIONS Contact: Content-Length: 0 Sep 5 15:23:57.954: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7F108C485D48 Sep 5 15:23:57.956: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 3 to index 4 Sep 5 15:23:57.956: //-1/xxxxxxxxxxxx/SIP/Info/notify/512/sip_tls_tcp_read_socket: ReadBlock nbytes 409 offset 0 Sep 5 15:23:57.956: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7F108C4E6718 with refCount = 1 Sep 5 15:23:57.956: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7F108C491000 with refCount = 1 Sep 5 15:23:57.956: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7F108C4E6718 Sep 5 15:23:57.956: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Sep 5 15:23:57.956: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x7F10FAD89E08 Sep 5 15:23:57.956: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x7F10FAD89E08, remote_addr=172.24.34.71, remote_port=5061, local_addr=172.24.34.162, local_port=50842, connid=4, transport=TLS Over TCP Sep 5 15:23:57.956: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 5061 connId 4 Sep 5 15:23:57.956: //126126/000000000000/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 200 OK Via: SIP/2.0/TLS 172.24.34.162:5061;branch=z9hG4bKF6B84D From: ;tag=2044CABD-21B To: ;tag=1638578063 Date: Mon, 05 Sep 2022 13:23:57 GMT Call-ID: D4ECD5EA-2C5411ED-ACE98A42-88ABFBF4@sbc.gram.sk Server: Cisco-CUCM12.5 CSeq: 101 OPTIONS Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 Sep 5 15:23:57.956: //126126/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 5 15:23:57.956: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Sep 5 15:23:57.957: //126126/000000000000/SIP/Info/info/1024/sipSPIMatchRespToReqTran: removing unneeded z9hG4bKF6B84D from via branch list Sep 5 15:23:57.957: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x7F108C491000) counter, current msg->refCount = 2 Sep 5 15:23:57.957: //126126/000000000000/SIP/Info/verbose/1024/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX Sep 5 15:23:57.957: //126126/000000000000/SIP/Info/info/4096/sipSPIHandle_ccsip_api_options_result: Optionsping feature disabled SIP_ADDR_INVALID = FALSE, Response_code = 200, Source = External, PingStatus NOT SAVED in Stack. Sep 5 15:23:57.957: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x7F108C491000) counter, current msg->refCount = 1 Sep 5 15:23:57.957: //126126/000000000000/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 1ECAE Sep 5 15:23:57.957: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[126491] removed. Sep 5 15:23:57.957: //126126/000000000000/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x7F10FDAFDF70 key=D4ECD5EA-2C5411ED-ACE98A42-88ABFBF4@sbc.gram.sk Sep 5 15:23:57.957: //126126/000000000000/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Sep 5 15:23:57.957: //126126/000000000000/SIP/Error/sipSPIFlushDeferredQueue: Invalid deferredQueue Sep 5 15:23:57.957: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x7F10FAD89E08, addr=172.24.34.71, port=5061, local_addr=172.24.34.162, unregistering context=0x7F10FDAFDF70 Sep 5 15:23:57.957: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x7F10FDAFDF70 from the connection=0x7F10FADC8BE8 context list Sep 5 15:23:57.957: //126126/000000000000/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Sep 5 15:23:57.957: //126126/000000000000/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer Sep 5 15:23:57.957: //126126/000000000000/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x7F10FDAFDF70 Sep 5 15:23:57.957: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[126491] Sep 5 15:23:57.957: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7F108C491000 Sep 5 15:24:28.514: %SIP-3-INTERNAL: Connection failed for addr=52.114.132.46, port=11522, connId=11135 sbc.gram.sk#