Cisco Voice Gateway - FreePBX Incoming calls issue

[KENNEDY BIZUAYEHU TADEGE]

Dear All,

we want to use cisco 2901 voice bundle router as a gateway for freepbx IP PBX. after creating SIP trunk between them, outgoing calls working but we're having issues on incoming calls are not reachable on freepbx extensions. after debugging we got below outputs and kindly advise.

Jan 28 12:19:10.270: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Calling Number=, Called Number=, Voice-Interface=0x310B6CCC,
Timeout=TRUE, Peer Encap Type=ENCAP_VOICE, Peer Search Type=PEER_TYPE_VOICE,
Peer Info Type=DIALPEER_INFO_SPEECH
Jan 28 12:19:10.270: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_PORT;
Jan 28 12:19:10.270: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Result=Success(0) after DP_MATCH_PORT; Incoming Dial-peer=1
Jan 28 12:19:10.270: //-1/xxxxxxxxxxxx/DPM/dpMatchSafModulePlugin:
dialstring=NULL, saf_enabled=0, saf_dndb_lookup=0, dp_result=0
Jan 28 12:19:10.274: //-1/38D81F7485A8/DPM/dpMatchPeersCore:
Calling Number=, Called Number=, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 28 12:19:10.274: //-1/38D81F7485A8/DPM/dpMatchPeersCore:
No Outgoing Dial-peer Is Matched; Result=NO_MATCH(-1)
Jan 28 12:19:10.274: //-1/38D81F7485A8/DPM/dpMatchSafModulePlugin:
dialstring=, saf_enabled=0, saf_dndb_lookup=1, dp_result=-1
Jan 28 12:19:10.274: //-1/38D81F7485A8/DPM/dpMatchPeersMoreArg:
Result=NO_MATCH(-1)
Jan 28 12:19:10.274: //-1/38D81F7485A8/DPM/dpMatchPeersCore:
Calling Number=, Called Number=, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 28 12:19:10.274: //-1/38D81F7485A8/DPM/dpMatchPeersCore:
No Outgoing Dial-peer Is Matched; Result=NO_MATCH(-1)
Jan 28 12:19:10.274: //-1/38D81F7485A8/DPM/dpMatchSafModulePlugin:
dialstring=, saf_enabled=0, saf_dndb_lookup=1, dp_result=-1
Jan 28 12:19:10.274: //-1/38D81F7485A8/DPM/dpMatchPeersMoreArg:
Result=NO_MATCH(-1)
Jan 28 12:19:10.274: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Calling Number=, Called Number=, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 28 12:19:10.274: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
No Outgoing Dial-peer Is Matched; Result=NO_MATCH(-1)
Jan 28 12:19:10.274: //-1/xxxxxxxxxxxx/DPM/dpMatchSafModulePlugin:
dialstring=, saf_enabled=0, saf_dndb_lookup=1, dp_result=-1
Jan 28 12:19:10.274: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersMoreArg:
Result=NO_MATCH(-1)
Jan 28 12:19:10.274: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Calling Number=, Called Number=, Voice-Interface=0x0,
Timeout=TRUE, Peer Encap Type=ENCAP_VOIP, Peer Search Type=PEER_TYPE_VOICE,
Peer Info Type=DIALPEER_INFO_SPEECH
Jan 28 12:19:10.274: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Result=NO_MATCH(-1) After All Match Rules Attempt
Jan 28 12:19:10.274: //-1/xxxxxxxxxxxx/DPM/dpMatchSafModulePlugin:
dialstring=NULL, saf_enabled=0, saf_dndb_lookup=0, dp_result=-1
Jan 28 12:19:10.274: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Calling Number=, Called Number=, Voice-Interface=0x0,
Timeout=TRUE, Peer Encap Type=ENCAP_VOIP, Peer Search Type=PEER_TYPE_VOICE,
Peer Info Type=DIALPEER_INFO_SPEECH
Jan 28 12:19:10.274: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Result=NO_MATCH(-1) After All Match Rules Attempt
Jan 28 12:19:10.274: //-1/xxxxxxxxxxxx/DPM/dpMatchSafModulePlugin:
dialstring=NULL, saf_enabled=0, saf_dndb_lookup=0, dp_result=-1
Jan 28 12:19:10.274: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Calling Number=, Called Number=, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 28 12:19:10.274: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
No Outgoing Dial-peer Is Matched; Result=NO_MATCH(-1)
VOIP-R#
Jan 28 12:19:10.274: //-1/xxxxxxxxxxxx/DPM/dpMatchSafModulePlugin:
dialstring=, saf_enabled=0, saf_dndb_lookup=1, dp_result=-1
Jan 28 12:19:10.274: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersMoreArg:
Result=NO_MATCH(-1)
Jan 28 12:19:11.714: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.1.242]:5060, local_address:[192.168.1.254]
Jan 28 12:19:11.714: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
Jan 28 12:19:11.714: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
OPTIONS sip:192.168.1.254:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.242:5060;rport;branch=z9hG4bKPja9d23998-988a-4a92-8b65-ef2bd54c45e9
From: <sip:Cisco-GW@192.168.1.242>;tag=617a5ab7-b2f4-44a9-95d0-1952790a55ee
To: <sip:192.168.1.254>
Contact: <sip:Cisco-GW@192.168.1.242:5060>
Call-ID: 76d2761d-1d4b-4f38-b6f1-68aa1ac414f0
CSeq: 28326 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-15.0.16.42(16.4.1)
Content-Length: 0

Jan 28 12:19:11.714: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
Jan 28 12:19:11.714: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x2B7205F0) with key=[4849] to table
Jan 28 12:19:11.714: //-1/000000000000/SIP/Info/ccsip_offer_ans_init:
Jan 28 12:19:11.714: //-1/000000000000/SIP/Info/ccsip_iwf_init:
Jan 28 12:19:11.714: //-1/000000000000/SIP/Info/ccsip_ipip_media_service_init:
Jan 28 12:19:11.714: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry...
Jan 28 12:19:11.714: //-1/000000000000/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 192.168.1.254
Jan 28 12:19:11.714: //-1/39B3D8A885AC/SIP/State/sipSPIChangeState: 0x2B7205F0 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
Jan 28 12:19:11.714: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/ccsipInitPldCallingInfo: non-numeric calling number: Cisco-GW
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPIGetViaHostInURLFormat: VIA URL:sip:192.168.1.242:5060, Host:192.168.1.242
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: : Cisco-GW
Jan 28 12:19:11.718: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Calling Number=Cisco-GW, Called Number=, Voice-Interface=0x0,
Timeout=TRUE, Peer Encap Type=ENCAP_VOIP, Peer Search Type=PEER_TYPE_VOICE,
Peer Info Type=DIALPEER_INFO_SPEECH
Jan 28 12:19:11.718: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ANSWER; Calling Number=Cisco-GW
Jan 28 12:19:11.718: //-1/xxxxxxxxxxxx/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 28 12:19:11.718: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=Cisco-GWT
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 28 12:19:11.718: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Result=-1
Jan 28 12:19:11.718: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ORIGINATE; Calling Number=Cisco-GW
Jan 28 12:19:11.718: //-1/xxxxxxxxxxxx/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 28 12:19:11.718: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=Cisco-GWT
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 28 12:19:11.718: //-1/xxxxxxxxxxxx/DPM/MatchNextPeer:
Result=Success(0); Incoming Dial-peer=200 Is Matched
Jan 28 12:19:11.718: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Result=Success(0) after DP_MATCH_ORIGINATE; Incoming Dial-peer=200
Jan 28 12:19:11.718: //-1/xxxxxxxxxxxx/DPM/dpMatchSafModulePlugin:
dialstring=NULL, saf_enabled=0, saf_dndb_lookup=0, dp_result=0
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPIGetFromCalledPartyId: P-Called-Party-ID header not found
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPIGetPeerByCalledPartyId: P-Called-Party-ID not found or parse error
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPIGetCallConfig: No match found for P-Called-Party-ID
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpAssociateIncomingPeerCore:
Calling Number=Cisco-GW, Called Number=, Voice-Interface=0x0,
Timeout=TRUE, Peer Encap Type=ENCAP_VOIP, Peer Search Type=PEER_TYPE_VOICE,
Peer Info Type=DIALPEER_INFO_SPEECH
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_VIA_URI; URI=sip:192.168.1.242:5060
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpMatchCore:
Result=-1
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_REQUEST_URI; URI=sip:192.168.1.254:5060
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpMatchCore:
Result=-1
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_TO_URI; URI=sip:192.168.1.254
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpMatchCore:
Result=-1
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_FROM_URI; URI=sip:Cisco-GW@192.168.1.242
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpMatchCore:
Result=-1
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ANSWER; Calling Number=Cisco-GW
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=Cisco-GWT
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpMatchCore:
Result=-1
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ORIGINATE; Calling Number=Cisco-GW
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=Cisco-GWT
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/MatchNextPeer:
Result=Success(0); Incoming Dial-peer=200 Is Matched
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpAssociateIncomingPeerCore:
Result=Success(0) after DP_MATCH_ORIGINATE; Incoming Dial-peer=200
Jan 28 12:19:11.718: //-1/39B3D8A885AC/DPM/dpMatchSafModulePlugin:
dialstring=NULL, saf_enabled=0, saf_dndb_lookup=0, dp_result=0
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPIGetCallConfig: Peer tag 200 matched for incoming call
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPICheckReliableProvStringtag: Unable to access supported header values
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 192.168.1.254
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPICheckReliableProvStringtag: Unable to access supported header values
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPIGetCallConfig: Media Antitrombone disabled
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPISetMediaFlowMode: Storing the configured mode as FLOW-THROUGH
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPISetMediaFlowMode: xcoder high-density disabled
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPISetMediaFlowMode: Flow Mode set to FLOW_THROUGH
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPIGetCallConfig: Checking Video Type Rate=-1 video_codec_allowed=1F
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPIGetModemInfoPerCall: peer_callID=0
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPIGetCallConfig: Media forking disabled
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPISetOverlapConfiguration: Overlap signaling: FALSE: Endpt: SIP Trunk
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/sipSPIValidateStreamAddrType: stream:1, Mode : 1
Jan 28 12:19:11.718: //4880/39B3D8A885AC/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 192.168.1.254
Jan 28 12:19:11.722: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_OPTIONS_RESP
Jan 28 12:19:11.722: //4880/39B3D8A885AC/SIP/Info/sact_idle_new_message_options: ccsip_api_options_ind returned: SIP_SUCCESS
Jan 28 12:19:11.722: //4880/39B3D8A885AC/SIP/State/sipSPIChangeState: 0x2B7205F0 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_NONE)
Jan 28 12:19:11.722: //4880/39B3D8A885AC/SIP/Info/sipSPIUaddCcbToUASReqTable: ****Adding to UAS Request table.
Jan 28 12:19:11.722: //4880/39B3D8A885AC/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x2B7205F0 key=76d2761d-1d4b-4f38-b6f1-68aa1ac414f0
Jan 28 12:19:11.722: //4880/39B3D8A885AC/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 1310 to table
Jan 28 12:19:11.722: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 38
Jan 28 12:19:11.722: //4880/39B3D8A885AC/SIP/Info/sipSPISendOptionsResponse: Associated container=0x2C05D114 to Options Response
Jan 28 12:19:11.722: //4880/39B3D8A885AC/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.242:5060;rport;branch=z9hG4bKPja9d23998-988a-4a92-8b65-ef2bd54c45e9
From: <sip:Cisco-GW@192.168.1.242>;tag=617a5ab7-b2f4-44a9-95d0-1952790a55ee
To: <sip:192.168.1.254>;tag=486367C-8F6
Date: Tue, 28 Jan 2020 12:19:11 GMT
Call-ID: 76d2761d-1d4b-4f38-b6f1-68aa1ac414f0
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 28326 OPTIONS
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Accept: appl
VOIP-R#ication/sdp
Supported: 100rel,timer,resource-priority,replaces,sdp-anat
Content-Type: application/sdp
Content-Length: 454

v=0
o=CiscoSystemsSIP-GW-UserAgent 9702 9580 IN IP4 192.168.1.254
s=SIP Call
c=IN IP4 192.168.1.254
t=0 0
m=audio 0 RTP/AVP 18 0 8 9 4 2 15
c=IN IP4 192.168.1.254
m=image 0 udptl t38
c=IN IP4 192.168.1.254
a=T38FaxVersion:0
a=T38MaxBitRate:9600
a=T38FaxFillBitRemoval:0
a=T38FaxTranscodingMMR:0
a=T38FaxTranscodingJBIG:0
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxBuffer:200
a=T38FaxMaxDatagram:320
a=T38FaxUdpEC:t38UDPRedundancy

Jan 28 12:19:15.970: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x2B758950) with key=[4850] to table
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/ccsip_offer_ans_init:
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/ccsip_iwf_init:
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/ccsip_ipip_media_service_init:
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry...
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/ccsipRegisterSetTargetInfo: p2p mode with Registrar Server = ipv4:192.168.1.242
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/ccsipRegisterSetTargetInfo: Parsing The Registrar Address
Jan 28 12:19:15.970: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetOutboundHostAndDestHostPrivate: CCSIP: target_host : 192.168.1.242 target_port : 5060

Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/sipSPIValidateAndCopyOutboundHost: CCSIP: copy target_host to outbound_host
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/sipSPIOutboundProxyReuse: Do not reuse Outbound Proxy IP adress and Port
Jan 28 12:19:15.970: //-1/000000000000/SIP/State/sipSPIChangeState: 0x2B758950 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/ccsip_spi_registrar_add_expires_header: Inside ccsip_spi_registrar_add_expires_header for Expires
Jan 28 12:19:15.970: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_OUTBOUND_REGISTER
Jan 28 12:19:15.970: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIIncrementOverloadCount: Local 1 Global 1
Jan 28 12:19:15.970: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x2B76F110) with key=[4851] to table
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/ccsip_offer_ans_init:
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/ccsip_iwf_init:
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/ccsip_ipip_media_service_init:
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry...
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/ccsipRegisterSetTargetInfo: p2p mode with Registrar Server = ipv4:192.168.1.242
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/ccsipRegisterSetTargetInfo: Parsing The Registrar Address
Jan 28 12:19:15.970: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetOutboundHostAndDestHostPrivate: CCSIP: target_host : 192.168.1.242 target_port : 5060

Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/sipSPIValidateAndCopyOutboundHost: CCSIP: copy target_host to outbound_host
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/sipSPIOutboundProxyReuse: Do not reuse Outbound Proxy IP adress and Port
Jan 28 12:19:15.970: //-1/000000000000/SIP/State/sipSPIChangeState: 0x2B76F110 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/ccsip_spi_registrar_add_expires_header: Inside ccsip_spi_registrar_add_expires_header for Expires
Jan 28 12:19:15.970: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_OUTBOUND_REGISTER
Jan 28 12:19:15.970: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIIncrementOverloadCount: Local 1 Global 2
Jan 28 12:19:15.970: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 40
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/act_idle_outgoing_register: In act_idle_outgoing_register

Jan 28 12:19:15.970: //4881/000000000000/SIP/Info/act_idle_outgoing_register: Send REGISTER to 192.168.1.242:5060

Jan 28 12:19:15.970: //4881/000000000000/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table.
Jan 28 12:19:15.970: //4881/000000000000/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x2B758950 key=7B3186B7-405711EA-808CDF05-B446D1E0
Jan 28 12:19:15.970: //4881/000000000000/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 192.168.1.254
Jan 28 12:19:15.970: //4881/000000000000/SIP/Info/sipSPIPresendProcessing: Presend Processing called for 7 event
Jan 28 12:19:15.970: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB
Jan 28 12:19:15.970: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB
Jan 28 12:19:15.970: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
Jan 28 12:19:15.970: //4881/000000000000/SIP/Info/sipSPISendRegister: Associated container=0x2C05DA5C to Register
Jan 28 12:19:15.970: //4881/000000000000/SIP/State/sipSPIChangeState: 0x2B758950 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE)
Jan 28 12:19:15.970: //4881/000000000000/SIP/State/sipSPIChangeState: 0x2B758950 : State change from (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE)
Jan 28 12:19:15.970: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 40
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/act_idle_outgoing_register: In act_idle_outgoing_register

Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/act_idle_outgoing_register: Send REGISTER to 192.168.1.242:5060

Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table.
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x2B76F110 key=7B30EA8F-405711EA-808ADF05-B446D1E0
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 192.168.1.254
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/sipSPIPresendProcessing: Presend Processing called for 7 event
Jan 28 12:19:15.970: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB
Jan 28 12:19:15.970: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB
Jan 28 12:19:15.970: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
Jan 28 12:19:15.970: //-1/000000000000/SIP/Info/sipSPISendRegister: Associated container=0x2C05C404 to Register
Jan 28 12:19:15.970: //-1/000000000000/SIP/State/sipSPIChangeState: 0x2B76F110 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE)
Jan 28 12:19:15.970: //-1/000000000000/SIP/State/sipSPIChangeState: 0x2B76F110 : State change from (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE)
Jan 28 12:19:15.974: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
REGISTER sip:192.168.1.242:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.254:5060;branch=z9hG4bKDF1AC0
From: <sip:111@192.168.1.242>;tag=486471C-C54
To: <sip:111@192.168.1.242>
Date: Tue, 28 Jan 2020 12:19:15 GMT
Call-ID: 7B3186B7-405711EA-808CDF05-B446D1E0
User-Agent: Cisco-SIPGateway/IOS-12.x
Max-Forwards: 70
Timestamp: 1580213955
CSeq: 397 REGISTER
Contact: <sip:111@192.168.1.254:5060>
Expires: 3600
Supported: path
Content-Length: 0

Jan 28 12:19:15.974: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
REGISTER sip:192.168.1.242:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.254:5060;branch=z9hG4bKDF2727
From: <sip:105@192.168.1.242>;tag=486471C-2FE
To: <sip:105@192.168.1.242>
Date: Tue, 28 Jan 2020 12:19:15 GMT
Call-ID: 7B30EA8F-405711EA-808ADF05-B446D1E0
User-Agent: Cisco-SIPGateway/IOS-12.x
Max-Forwards: 70
Timestamp: 1580213955
CSeq: 397 REGISTER
Contact: <sip:105@192.168.1.254:5060>
Expires: 3600
Supported: path
Content-Length: 0

Jan 28 12:19:15.974: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.1.242]:5060, local_address:[192.168.1.254]
Jan 28 12:19:15.974: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.1.242]:5060, local_address:[192.168.1.254]
Jan 28 12:19:15.974: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
Jan 28 12:19:15.974: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
Jan 28 12:19:15.974: //4881/000000000000/SIP/Info/sipSPIMatchRespToReqTran: removing unneeded z9hG4bKDF1AC0 from via branch list
Jan 28 12:19:15.974: //4881/000000000000/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP 192.168.1.254:5060;rport=55378;received=192.168.1.254;branch=z9hG4bKDF1AC0
Call-ID: 7B3186B7-405711EA-808CDF05-B446D1E0
From: <sip:111@192.168.1.242>;tag=486471C-C54
To: <sip:111@192.168.1.242>;tag=z9hG4bKDF1AC0
CSeq: 397 REGISTER
Server: FPBX-15.0.16.42(16.4.1)
Content-Length: 0

Jan 28 12:19:15.974: //4881/000000000000/SIP/Info/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX
Jan 28 12:19:15.974: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDecrementOverloadCount: Count:Local 0 Global 1
Jan 28 12:19:15.974: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_register_reset_dns_cache: CCSIP_REGISTER:: registrar 0 DNS resolved addr reset
Jan 28 12:19:15.974: //4881/000000000000/SIP/Info/sipSPIRegPthruProcessResponse: Processing response w/ resp code == 404
Jan 28 12:19:15.974: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetRPCBFromRCB: Retreiving RCB [0x30012098] from RPCB [0x0]
Jan 28 12:19:15.974: //-1/xxxxxxxxxxxx/SIP/Info/ccsipRegisterStartRCBTimer: Starting timer for pattern 111 for 180 seconds
Jan 28 12:19:15.974: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[4850] removed.
Jan 28 12:19:15.974: //4881/000000000000/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table.
Jan 28 12:19:15.974: //4881/000000000000/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x2B758950 key=7B3186B7-405711EA-808CDF05-B446D1E0
Jan 28 12:19:15.974: //4881/000000000000/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
Jan 28 12:19:15.974: //4881/000000000000/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
Jan 28 12:19:15.974: //4881/000000000000/SIP/Info/ccsip_offer_ans_delete:
Jan 28 12:19:15.974: //4881/000000000000/SIP/Info/ccsip_iwf_delete:
Jan 28 12:19:15.974: //4881/000000000000/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 2B758950
Jan 28 12:19:15.974: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[4850]
Jan 28 12:19:15.974: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
Jan 28 12:19:15.974: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
Jan 28 12:19:15.974: //-1/000000000000/SIP/Info/sipSPIMatchRespToReqTran: removing unneeded z9hG4bKDF2727 from via branch list
Jan 28 12:19:15.974: //-1/000000000000/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP 192.168.1.254:5060;rport=55378;received=192.168.1.254;branch=z9hG4bKDF2727
Call-ID: 7B30EA8F-405711EA-808ADF05-B446D1E0
From: <sip:105@192.168.1.242>;tag=486471C-2FE
To: <sip:105@192.168.1.242>;tag=z9hG4bKDF2727
CSeq: 397 REGISTER
Server: FPBX-15.0.16.42(16.4.1)
Content-Length: 0

Jan 28 12:19:15.974: //-1/000000000000/SIP/Info/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX
Jan 28 12:19:15.974: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDecrementOverloadCount: Count:Local 0 Global 0
Jan 28 12:19:15.974: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_register_reset_dns_cache: CCSIP_REGISTER:: registrar 0 DNS resolved addr reset
Jan 28 12:19:15.974: //-1/000000000000/SIP/Info/sipSPIRegPthruProcessResponse: Processing response w/ resp code == 404
Jan 28 12:19:15.974: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetRPCBFromRCB: Retreiving RCB [0x3071696C] from RPCB [0x0]
Jan 28 12:19:15.978: //-1/xxxxxxxxxxxx/SIP/Info/ccsipRegisterStartRCBTimer: Starting timer for pattern 105 for 180 seconds
Jan 28 12:19:15.978: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[4851] removed.
Jan 28 12:19:15.978: //-1/000000000000/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table.
Jan 28 12:19:15.978: //-1/000000000000/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x2B76F110 key=7B30EA8F-405711EA-808ADF05-B446D1E0
Jan 28 12:19:15.978: //-1/000000000000/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
Jan 28 12:19:15.978: //-1/000000000000/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
Jan 28 12:19:15.978: //-1/000000000000/SIP/Info/ccsip_offer_ans_delete:
Jan 28 12:19:15.978: //-1/000000000000/SIP/Info/ccsip_iwf_delete:
Jan 28 12:19:15.978: //4882/000000000000/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 2B76F110
Jan 28 12:19:15.978: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[4851]

[Muhammad Awais Khan]

Hi,

Is there dial-peer configure from VG to PBX internal extensions for inbound calls from PSTN ? I saw "No Outgoing Dial-peer Is Matched" in above logs. 

Can you share dial-peer config for review ?

[KENNEDY BIZUAYEHU TADEGE]

Hi,

Thanks for your response.

i didn't configure dial peer, pls see below router config. since I'm new to Cisco VG, pls help how to add dial peers.

regards

VOIP-R#sh run
Building configuration...

Current configuration : 5925 bytes
!
! Last configuration change at 16:18:28 UTC Mon Jan 27 2020 by symbol
version 15.1
service timestamps debug datetime msec
service timestamps log datetime msec
no service password-encryption
!
hostname VOIP-R
!
boot-start-marker
boot-end-marker
!
!
card type e1 0 2
!
no aaa new-model
network-clock-participate wic 2
!
no ipv6 cef
ip source-route
ip cef
!
!
!
!
!
multilink bundle-name authenticated
!
!
!
!
isdn switch-type primary-net5
!
crypto pki token default removal timeout 0
!
crypto pki trustpoint TP-self-signed-3072723400
enrollment selfsigned
subject-name cn=IOS-Self-Signed-Certificate-3072723400
revocation-check none
rsakeypair TP-self-signed-3072723400
!
!
voice-card 0
dspfarm
dsp services dspfarm
!
!
!
voice service voip
allow-connections h323 to h323
allow-connections h323 to sip
allow-connections sip to h323
allow-connections sip to sip
redirect ip2ip
signaling forward unconditional
fax protocol t38 version 0 ls-redundancy 0 hs-redundancy 0 fallback none
sip
bind control source-interface GigabitEthernet0/0
bind media source-interface GigabitEthernet0/0
!
!
!
!
!
license udi pid CISCO2901/K9 sn FCZ163020WV
hw-module pvdm 0/0
!
hw-module pvdm 0/1
!
!
!
username symbol privilege 15 password 0 passwd
username admin password 0 admin
!
redundancy
!
!
controller E1 0/2/0
framing NO-CRC4
pri-group timeslots 1-16
!
!
!
!
!
interface Loopback0
ip address 192.168.10.10 255.255.255.0
!
interface Embedded-Service-Engine0/0
no ip address
shutdown
!
interface GigabitEthernet0/0
ip address 192.168.1.254 255.255.255.0
duplex auto
speed auto
!
interface GigabitEthernet0/1
no ip address
shutdown
duplex auto
speed auto
!
interface Serial0/2/0:15
no ip address
encapsulation hdlc
isdn switch-type primary-net5
isdn incoming-voice voice
no cdp enable
!
ip forward-protocol nd
!
ip http server
ip http authentication local
ip http secure-server
!
ip route 0.0.0.0 0.0.0.0 192.168.1.1
!
!
!
!
control-plane
!
!
voice-port 0/0/0
!
voice-port 0/0/1
!
voice-port 0/0/2
!
voice-port 0/0/3
!
voice-port 0/2/0:15
!
voice-port 0/1/0
!
voice-port 0/1/1
!
voice-port 0/1/2
!
voice-port 0/1/3
!
ccm-manager mgcp
ccm-manager config
!
mgcp
!
mgcp profile default
!
!
dial-peer voice 2 pots
description Outside Call
destination-pattern .T
port 0/0/1
forward-digits all
!
dial-peer voice 3 pots
description Outside Call
destination-pattern .T
port 0/0/2
forward-digits all
!
dial-peer voice 200 voip
description FreePBX-Trunk
numbering-type unknown
destination-pattern .
session protocol sipv2
session target ipv4:192.168.1.242:5060
session transport udp
dtmf-relay rtp-nte
codec g711ulaw
!
dial-peer voice 1 pots
description Outside Call
destination-pattern .T
incoming called-number .
port 0/0/0
forward-digits all
!
dial-peer voice 4 pots
description Outside Call
destination-pattern .T
port 0/0/3
forward-digits all
!
!
gateway
timer receive-rtp 1200
!
sip-ua
credentials username xyz password 7 044B0A151C3648 realm xyz
credentials username wsx password 7 03145A18151825 realm freepbx
no remote-party-id
retry invite 3
retry response 3
retry bye 3
retry cancel 3
timers trying 1000
registrar ipv4:192.168.1.242 expires 3600
sip-server ipv4:192.168.1.242
!
!
!
gatekeeper
shutdown
!
!
telephony-service
max-ephones 35
max-dn 35
ip source-address 192.168.1.254 port 2000
max-conferences 8 gain -6
transfer-system full-consult
!
!
!
!
!
!
line con 0
line aux 0
line 2
no activation-character
no exec
transport preferred none
transport input all
transport output pad telnet rlogin lapb-ta mop udptn v120 ssh
stopbits 1
line vty 0 4
privilege level 15
login local
transport input telnet ssh
!
scheduler allocate 20000 1000
end

[Muhammad Awais Khan · Accepted solution]

Hi,

I found some issues. You are using Analogue FXO ports, when call hits these ports then you have to send these calls to an extension in PBX. To send incomming calls, you need to define which extension/pilot/Auto Attendant should receive the call from outside.

For example, lets say you want to receive calls from outside on all ports to 105, then you need to add following to your config:

voice-port 0/0/0

connection plar opx 105
!
voice-port 0/0/1

connection plar opx 105
!
voice-port 0/0/2

connection plar opx 105
!
voice-port 0/0/3

connection plar opx 105

! Next step, you should have dial-peer matching your internal extension range. I have notice you have dial-peer 200 defined but with . as destination-match. It is going to over-lap with existing dial-peer. It seems your internal extensions started from 1, so lets me modify it:

dial-peer voice 200 voip
description FreePBX-Trunk
numbering-type unknown
destination-pattern 1..
session protocol sipv2
session target ipv4:192.168.1.242:5060
session transport udp
dtmf-relay rtp-nte
codec g711ulaw

!

above dial-peer is going to match any number starts with 1 with extension length of 3. If you have different ranges then let me know. I can enhance the dial-peer. 

[KENNEDY BIZUAYEHU TADEGE]

Hi Muhammad,

I did exactly what you've suggested and it worked perfectly.

Many Thanks !

Regards

[Muhammad Awais Khan]

I am glad to hear that it worked out for you! Keep posting here or ping me for any further issue :)

[KENNEDY BIZUAYEHU TADEGE]

Hi Muhamad,

Many thanks very valuable support.

One new issue after the system started to work is i couldn't make and accept both outgoing and incoming calls from freepbx sip phones.

below are debug outputs for outgoing calls from freepbx sip phones to pstn and if you want i can post debugs for the incoming also.

Error from sip phone while making outgoing call is "All circuits are busy now, please try your call again later" and when i see the gateway all 8 FXO ports are green but noone is using the lines.

Jan 30 14:20:59.115: //2514/7F0163C386E6/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 9D2
Jan 30 14:20:59.115: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[2473] removed.
Jan 30 14:20:59.115: //2514/7F0163C386E6/SIP/Info/sipSPIUdeleteCcbFromUASReqTable: ****Deleting from UAS Request table.
Jan 30 14:20:59.115: //2514/7F0163C386E6/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x2B77F4F0 key=a8302158-7189-45d3-9f91-46f974ea2a5acisco
Jan 30 14:20:59.115: //2514/7F0163C386E6/SIP/Info/sipSPIUdeleteCcbFromUASRespTable: ****Deleting from UAS Response table.
Jan 30 14:20:59.115: //2514/7F0163C386E6/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
Jan 30 14:20:59.115: //2514/7F0163C386E6/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
Jan 30 14:20:59.115: //2514/7F0163C386E6/SIP/Info/ccsip_offer_ans_delete:
Jan 30 14:20:59.115: //2514/7F0163C386E6/SIP/Info/ccsip_iwf_delete:
Jan 30 14:20:59.115: //2514/7F0163C386E6/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 2B77F4F0
Jan 30 14:21:02.655: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x2B77F4F0) with key=[2479] to table
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/ccsip_offer_ans_init:
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/ccsip_iwf_init:
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/ccsip_ipip_media_service_init:
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry...
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/ccsipRegisterSetTargetInfo: p2p mode with Registrar Server = ipv4:192.168.1.242
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/ccsipRegisterSetTargetInfo: Parsing The Registrar Address
Jan 30 14:21:02.655: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetOutboundHostAndDestHostPrivate: CCSIP: target_host : 192.168.1.242 target_port : 5060

Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/sipSPIValidateAndCopyOutboundHost: CCSIP: copy target_host to outbound_host
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/sipSPIOutboundProxyReuse: Do not reuse Outbound Proxy IP adress and Port
Jan 30 14:21:02.655: //-1/000000000000/SIP/State/sipSPIChangeState: 0x2B77F4F0 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/ccsip_spi_registrar_add_expires_header: Inside ccsip_spi_registrar_add_expires_header for Expires
Jan 30 14:21:02.655: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_OUTBOUND_REGISTER
Jan 30 14:21:02.655: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIIncrementOverloadCount: Local 1 Global 1
Jan 30 14:21:02.655: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x2B763340) with key=[2480] to table
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/ccsip_offer_ans_init:
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/ccsip_iwf_init:
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/ccsip_ipip_media_service_init:
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry...
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/ccsipRegisterSetTargetInfo: p2p mode with Registrar Server = ipv4:192.168.1.242
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/ccsipRegisterSetTargetInfo: Parsing The Registrar Address
Jan 30 14:21:02.655: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetOutboundHostAndDestHostPrivate: CCSIP: target_host : 192.168.1.242 target_port : 5060

Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/sipSPIValidateAndCopyOutboundHost: CCSIP: copy target_host to outbound_host
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/sipSPIOutboundProxyReuse: Do not reuse Outbound Proxy IP adress and Port
Jan 30 14:21:02.655: //-1/000000000000/SIP/State/sipSPIChangeState: 0x2B763340 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/ccsip_spi_registrar_add_expires_header: Inside ccsip_spi_registrar_add_expires_header for Expires
Jan 30 14:21:02.655: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_OUTBOUND_REGISTER
Jan 30 14:21:02.655: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIIncrementOverloadCount: Local 1 Global 2
Jan 30 14:21:02.655: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 40
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/act_idle_outgoing_register: In act_idle_outgoing_register

Jan 30 14:21:02.655: //2520/000000000000/SIP/Info/act_idle_outgoing_register: Send REGISTER to 192.168.1.242:5060

Jan 30 14:21:02.655: //2520/000000000000/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table.
Jan 30 14:21:02.655: //2520/000000000000/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x2B77F4F0 key=338625A6-427811EA-8007B591-EFBDCE88
Jan 30 14:21:02.655: //2520/000000000000/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 192.168.1.254
Jan 30 14:21:02.655: //2520/000000000000/SIP/Info/sipSPIPresendProcessing: Presend Processing called for 7 event
Jan 30 14:21:02.655: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB
Jan 30 14:21:02.655: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB
Jan 30 14:21:02.655: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
Jan 30 14:21:02.655: //2520/000000000000/SIP/Info/sipSPISendRegister: Associated container=0x320F48E8 to Register
Jan 30 14:21:02.655: //2520/000000000000/SIP/State/sipSPIChangeState: 0x2B77F4F0 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE)
Jan 30 14:21:02.655: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 40
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/act_idle_outgoing_register: In act_idle_outgoing_register

Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/act_idle_outgoing_register: Send REGISTER to 192.168.1.242:5060

Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table.
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x2B763340 key=339910DF-427811EA-8008B591-EFBDCE88
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 192.168.1.254
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/sipSPIPresendProcessing: Presend Processing called for 7 event
Jan 30 14:21:02.655: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB
Jan 30 14:21:02.655: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB
Jan 30 14:21:02.655: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
Jan 30 14:21:02.655: //-1/000000000000/SIP/Info/sipSPISendRegister: Associated container=0x320F41B0 to Register
Jan 30 14:21:02.655: //-1/000000000000/SIP/State/sipSPIChangeState: 0x2B763340 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE)
Jan 30 14:21:02.655: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 56
Jan 30 14:21:02.655: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 61
Jan 30 14:21:02.659: //2520/000000000000/SIP/State/sipSPIChangeState: 0x2B77F4F0 : State change from (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE)
Jan 30 14:21:02.659: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 61
Jan 30 14:21:02.659: //-1/000000000000/SIP/State/sipSPIChangeState: 0x2B763340 : State change from (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE)
Jan 30 14:21:02.659: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
REGISTER sip:192.168.1.242:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.254:5060;branch=z9hG4bK3641DDC
From: <sip:104@192.168.1.242>;tag=1036A68-BE9
To: <sip:104@192.168.1.242>
Date: Thu, 30 Jan 2020 14:21:02 GMT
Call-ID: 338625A6-427811EA-8007B591-EFBDCE88
User-Agent: Cisco-SIPGateway/IOS-12.x
Max-Forwards: 70
Timestamp: 1580394062
CSeq: 96 REGISTER
Contact: <sip:104@192.168.1.254:5060>
Expires: 3600
Supported: path
Content-Length: 0

Jan 30 14:21:02.659: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
REGISTER sip:192.168.1.242:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.254:5060;branch=z9hG4bK365C4
From: <sip:105@192.168.1.242>;tag=1036A68-1347
To: <sip:105@192.168.1.242>
Date: Thu, 30 Jan 2020 14:21:02 GMT
Call-ID: 339910DF-427811EA-8008B591-EFBDCE88
User-Agent: Cisco-SIPGateway/IOS-12.x
Max-Forwards: 70
Timestamp: 1580394062
CSeq: 96 REGISTER
Contact: <sip:105@192.168.1.254:5060>
Expires: 3600
Supported: path
Content-Length: 0

Jan 30 14:21:03.159: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
Jan 30 14:21:03.159: //2520/000000000000/SIP/Info/sipSPISendRegister: Associated container=0x320F48E8 to Register
Jan 30 14:21:03.159: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
Jan 30 14:21:03.159: //-1/000000000000/SIP/Info/sipSPISendRegister: Associated container=0x320F41B0 to Register
Jan 30 14:21:03.159: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 55
Jan 30 14:21:03.159: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 53
Jan 30 14:21:03.159: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDecrementOverloadCount: Count:Local 0 Global 1
Jan 30 14:21:03.159: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_register_reset_dns_cache: CCSIP_REGISTER:: registrar 0 DNS resolved addr reset
Jan 30 14:21:03.159: //2520/000000000000/SIP/Info/sipSPIRegPthruProcessResponse: Processing response w/ resp code == 5
Jan 30 14:21:03.159: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetRPCBFromRCB: Retreiving RCB [0x2B9473C0] from RPCB [0x0]
Jan 30 14:21:03.159: //-1/xxxxxxxxxxxx/SIP/Info/ccsipRegisterStartRCBTimer: Starting timer for pattern 104 for 180 seconds
Jan 30 14:21:03.159: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[2479] removed.
Jan 30 14:21:03.159: //2520/000000000000/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table.
Jan 30 14:21:03.159: //2520/000000000000/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x2B77F4F0 key=338625A6-427811EA-8007B591-EFBDCE88
Jan 30 14:21:03.159: //2520/000000000000/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
Jan 30 14:21:03.159: //2520/000000000000/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
Jan 30 14:21:03.159: //2520/000000000000/SIP/Info/ccsip_offer_ans_delete:
Jan 30 14:21:03.159: //2520/000000000000/SIP/Info/ccsip_iwf_delete:
Jan 30 14:21:03.159: //2520/000000000000/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 2B77F4F0
Jan 30 14:21:03.159: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[2479]
Jan 30 14:21:03.159: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 53
Jan 30 14:21:03.159: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDecrementOverloadCount: Count:Local 0 Global 0
Jan 30 14:21:03.159: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_register_reset_dns_cache: CCSIP_REGISTER:: registrar 0 DNS resolved addr reset
Jan 30 14:21:03.159: //-1/000000000000/SIP/Info/sipSPIRegPthruProcessResponse: Processing response w/ resp code == 5
Jan 30 14:21:03.159: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetRPCBFromRCB: Retreiving RCB [0x318B46BC] from RPCB [0x0]
Jan 30 14:21:03.159: //-1/xxxxxxxxxxxx/SIP/Info/ccsipRegisterStartRCBTimer: Starting timer for pattern 105 for 180 seconds
Jan 30 14:21:03.159: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[2480] removed.
Jan 30 14:21:03.159: //-1/000000000000/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table.
Jan 30 14:21:03.159: //-1/000000000000/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x2B763340 key=339910DF-427811EA-8008B591-EFBDCE88
Jan 30 14:21:03.159: //-1/000000000000/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
Jan 30 14:21:03.159: //-1/000000000000/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
Jan 30 14:21:03.159: //-1/000000000000/SIP/Info/ccsip_offer_ans_delete:
Jan 30 14:21:03.159: //-1/000000000000/SIP/Info/ccsip_iwf_delete:
Jan 30 14:21:03.159: //2521/000000000000/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 2B763340
Jan 30 14:21:03.159: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[2480]
Jan 30 14:21:03.159: //-1/xxxxxxxxxxxx/SIP/Info/udpsock_close_connect: Socket fd: 1 closed for connid 3 with remote port: 5060
Jan 30 14:21:03.611: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.1.242]:5060, local_address:[192.168.1.254]
Jan 30 14:21:03.611: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
Jan 30 14:21:03.611: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
OPTIONS sip:cisco@192.168.1.254:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.242:5060;rport;branch=z9hG4bKPjbb6831cc-9047-42ac-88f5-caa8b0cc08b5
From: <sip:Cisco-GW@192.168.1.242>;tag=463bc7a8-c52f-42d2-826b-a542273b98cb
To: <sip:cisco@192.168.1.254>
Contact: <sip:Cisco-GW@192.168.1.242:5060>
Call-ID: bccf2289-9947-44a9-916b-bcd67641a3b3
CSeq: 49156 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-15.0.16.42(16.4.1)
Content-Length: 0

Jan 30 14:21:03.615: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
Jan 30 14:21:03.615: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x2B763340) with key=[2481] to table
Jan 30 14:21:03.615: //-1/000000000000/SIP/Info/ccsip_offer_ans_init:
Jan 30 14:21:03.615: //-1/000000000000/SIP/Info/ccsip_iwf_init:
Jan 30 14:21:03.615: //-1/000000000000/SIP/Info/ccsip_ipip_media_service_init:
Jan 30 14:21:03.615: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry...
Jan 30 14:21:03.615: //-1/000000000000/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 192.168.1.254
Jan 30 14:21:03.615: //-1/94C2D80086E7/SIP/State/sipSPIChangeState: 0x2B763340 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
Jan 30 14:21:03.615: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
Jan 30 14:21:03.615: //2522/94C2D80086E7/SIP/Info/ccsipInitPldCallingInfo: non-numeric calling number: Cisco-GW
Jan 30 14:21:03.615: //2522/94C2D80086E7/SIP/Info/sipSPIGetViaHostInURLFormat: VIA URL:sip:192.168.1.242:5060, Host:192.168.1.242
Jan 30 14:21:03.615: //2522/94C2D80086E7/SIP/Info/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: : Cisco-GW
Jan 30 14:21:03.615: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Calling Number=Cisco-GW, Called Number=, Voice-Interface=0x0,
Timeout=TRUE, Peer Encap Type=ENCAP_VOIP, Peer Search Type=PEER_TYPE_VOICE,
Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:03.615: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ANSWER; Calling Number=Cisco-GW
Jan 30 14:21:03.615: //-1/xxxxxxxxxxxx/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:03.615: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=Cisco-GWT
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:03.615: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:03.615: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ORIGINATE; Calling Number=Cisco-GW
Jan 30 14:21:03.615: //-1/xxxxxxxxxxxx/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:03.615: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=Cisco-GWT
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:03.615: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:03.615: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Result=NO_MATCH(-1) After All Match Rules Attempt
Jan 30 14:21:03.615: //-1/xxxxxxxxxxxx/DPM/dpMatchSafModulePlugin:
dialstring=NULL, saf_enabled=0, saf_dndb_lookup=0, dp_result=-1
Jan 30 14:21:03.615: //2522/94C2D80086E7/SIP/Info/sipSPIGetFromCalledPartyId: P-Called-Party-ID header not found
Jan 30 14:21:03.615: //2522/94C2D80086E7/SIP/Info/sipSPIGetPeerByCalledPartyId: P-Called-Party-ID not found or parse error
Jan 30 14:21:03.615: //2522/94C2D80086E7/SIP/Info/sipSPIGetCallConfig: No match found for P-Called-Party-ID
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpAssociateIncomingPeerCore:
Calling Number=Cisco-GW, Called Number=, Voice-Interface=0x0,
Timeout=TRUE, Peer Encap Type=ENCAP_VOIP, Peer Search Type=PEER_TYPE_VOICE,
Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_VIA_URI; URI=sip:192.168.1.242:5060
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_REQUEST_URI; URI=sip:cisco@192.168.1.254:5060
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_TO_URI; URI=sip:cisco@192.168.1.254
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_FROM_URI; URI=sip:Cisco-GW@192.168.1.242
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ANSWER; Calling Number=Cisco-GW
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=Cisco-GWT
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ORIGINATE; Calling Number=Cisco-GW
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=Cisco-GWT
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:03.615: //-1/94C2D80086E7/DPM/dpAssociateIncomingPeerCore:
Result=NO_MATCH(-1) After All Match Rules Attempt
Jan 30 14:21:03.619: //-1/94C2D80086E7/DPM/dpMatchSafModulePlugin:
dialstring=NULL, saf_enabled=0, saf_dndb_lookup=0, dp_result=-1
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPICheckReliableProvStringtag: Unable to access supported header values
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPIGetCallConfig: Media Antitrombone disabled
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPISetMediaFlowMode: Storing the configured mode as FLOW-THROUGH
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPISetMediaFlowMode: xcoder high-density disabled
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPISetMediaFlowMode: Flow Mode set to FLOW_THROUGH
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPIGetCallConfig: Non dial peer leg - using RTP Supported Codecs
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 18
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 0
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 8
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 9
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 4
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 2
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 15
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 255
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPIGetModemInfoPerCall: peer_callID=0
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPISetOverlapConfiguration: Overlap signaling: FALSE: Endpt: SIP Trunk
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPIValidateStreamAddrType: stream:1, Mode : 1
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 192.168.1.254
Jan 30 14:21:03.619: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_OPTIONS_RESP
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sact_idle_new_message_options: ccsip_api_options_ind returned: SIP_SUCCESS
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/State/sipSPIChangeState: 0x2B763340 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_NONE)
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPIUaddCcbToUASReqTable: ****Adding to UAS Request table.
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x2B763340 key=bccf2289-9947-44a9-916b-bcd67641a3b3cisco
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 9DA to table
Jan 30 14:21:03.619: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 38
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Info/sipSPISendOptionsResponse: Associated container=0x320F5C28 to Options Response
Jan 30 14:21:03.619: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 56
Jan 30 14:21:03.619: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 61
Jan 30 14:21:03.619: //2522/94C2D80086E7/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.242:5060;rport;branch=z9hG4bKPjbb6831cc-9047-42ac-88f5-caa8b0cc08b5
From: <sip:Cisco-GW@192.168.1.242>;tag=463bc7a8-c52f-42d2-826b-a542273b98cb
To: <sip:cisco@192.168.1.254>;tag=1036E28-1D28
Date: Thu, 30 Jan 2020 14:21:03 GMT
Call-ID: bccf2289-9947-44a9-916b-bcd67641a3b3
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 49156 OPTIONS
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Accept: application/sdp
Supported: 100rel,timer,resource-priority,replaces,sdp-anat
Content-Type: application/sdp
Content-Length: 453

v=0
o=CiscoSystemsSIP-GW-UserAgent 151 4307 IN IP4 192.168.1.254
s=SIP Call
c=IN IP4 192.168.1.254
t=0 0
m=audio 0 RTP/AVP 18 0 8 9 4 2 15
c=IN IP4 192.168.1.254
m=image 0 udptl t38
c=IN IP4 192.168.1.254
a=T38FaxVersion:0
a=T38MaxBitRate:9600
a=T38FaxFillBitRemoval:0
a=T38FaxTranscodingMMR:0
a=T38FaxTranscodingJBIG:0
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxBuffer:200
a=T38FaxMaxDatagram:320
a=T38FaxUdpEC:t38UDPRedundancy

Jan 30 14:21:04.115: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.1.242]:5060, local_address:[192.168.1.254]
Jan 30 14:21:04.115: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
Jan 30 14:21:04.115: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
OPTIONS sip:cisco@192.168.1.254:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.242:5060;rport;branch=z9hG4bKPjbb6831cc-9047-42ac-88f5-caa8b0cc08b5
From: <sip:Cisco-GW@192.168.1.242>;tag=463bc7a8-c52f-42d2-826b-a542273b98cb
To: <sip:cisco@192.168.1.254>
Contact: <sip:Cisco-GW@192.168.1.242:5060>
Call-ID: bccf2289-9947-44a9-916b-bcd67641a3b3
CSeq: 49156 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-15.0.16.42(16.4.1)
Content-Length: 0

Jan 30 14:21:04.115: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
Jan 30 14:21:04.115: //2522/94C2D80086E7/SIP/Info/sipSPIFindCcbUASReqTable: *****CCB found in UAS Request table. ccb=0x2B763340
Jan 30 14:21:04.115: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
Jan 30 14:21:04.115: //2522/94C2D80086E7/SIP/Info/sipSPISendOptionsResponse: Associated container=0x320F5C28 to Options Response
Jan 30 14:21:04.115: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 55
Jan 30 14:21:04.115: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 53
Jan 30 14:21:04.115: //2522/94C2D80086E7/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 9DA
Jan 30 14:21:04.115: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[2481] removed.
Jan 30 14:21:04.115: //2522/94C2D80086E7/SIP/Info/sipSPIUdeleteCcbFromUASReqTable: ****Deleting from UAS Request table.
Jan 30 14:21:04.115: //2522/94C2D80086E7/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x2B763340 key=bccf2289-9947-44a9-916b-bcd67641a3b3cisco
Jan 30 14:21:04.115: //2522/94C2D80086E7/SIP/Info/sipSPIUdeleteCcbFromUASRespTable: ****Deleting from UAS Response table.
Jan 30 14:21:04.115: //2522/94C2D80086E7/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
Jan 30 14:21:04.115: //2522/94C2D80086E7/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
Jan 30 14:21:04.115: //2522/94C2D80086E7/SIP/Info/ccsip_offer_ans_delete:
Jan 30 14:21:04.115: //2522/94C2D80086E7/SIP/Info/ccsip_iwf_delete:
Jan 30 14:21:04.115: //2522/94C2D80086E7/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 2B763340
Jan 30 14:21:04.115: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[2481]
Jan 30 14:21:04.115: //-1/xxxxxxxxxxxx/SIP/Info/udpsock_close_connect: Socket fd: 1 closed for connid 3 with remote port: 5060
Jan 30 14:21:05.115: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.1.242]:5060, local_address:[192.168.1.254]
Jan 30 14:21:05.115: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
Jan 30 14:21:05.115: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
OPTIONS sip:cisco@192.168.1.254:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.242:5060;rport;branch=z9hG4bKPjbb6831cc-9047-42ac-88f5-caa8b0cc08b5
From: <sip:Cisco-GW@192.168.1.242>;tag=463bc7a8-c52f-42d2-826b-a542273b98cb
To: <sip:cisco@192.168.1.254>
Contact: <sip:Cisco-GW@192.168.1.242:5060>
Call-ID: bccf2289-9947-44a9-916b-bcd67641a3b3
CSeq: 49156 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-15.0.16.42(16.4.1)
Content-Length: 0

Jan 30 14:21:05.115: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
Jan 30 14:21:05.115: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x2B763340) with key=[2482] to table
Jan 30 14:21:05.115: //-1/000000000000/SIP/Info/ccsip_offer_ans_init:
Jan 30 14:21:05.115: //-1/000000000000/SIP/Info/ccsip_iwf_init:
Jan 30 14:21:05.115: //-1/000000000000/SIP/Info/ccsip_ipip_media_service_init:
Jan 30 14:21:05.115: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry...
Jan 30 14:21:05.115: //-1/000000000000/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 192.168.1.254
Jan 30 14:21:05.115: //-1/95A7BAC386E8/SIP/State/sipSPIChangeState: 0x2B763340 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
Jan 30 14:21:05.115: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
Jan 30 14:21:05.115: //2523/95A7BAC386E8/SIP/Info/ccsipInitPldCallingInfo: non-numeric calling number: Cisco-GW
Jan 30 14:21:05.115: //2523/95A7BAC386E8/SIP/Info/sipSPIGetViaHostInURLFormat: VIA URL:sip:192.168.1.242:5060, Host:192.168.1.242
Jan 30 14:21:05.115: //2523/95A7BAC386E8/SIP/Info/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: : Cisco-GW
Jan 30 14:21:05.115: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Calling Number=Cisco-GW, Called Number=, Voice-Interface=0x0,
Timeout=TRUE, Peer Encap Type=ENCAP_VOIP, Peer Search Type=PEER_TYPE_VOICE,
Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:05.115: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ANSWER; Calling Number=Cisco-GW
Jan 30 14:21:05.115: //-1/xxxxxxxxxxxx/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:05.115: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=Cisco-GWT
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:05.115: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:05.115: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ORIGINATE; Calling Number=Cisco-GW
Jan 30 14:21:05.115: //-1/xxxxxxxxxxxx/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:05.115: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=Cisco-GWT
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:05.115: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:05.115: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Result=NO_MATCH(-1) After All Match Rules Attempt
Jan 30 14:21:05.115: //-1/xxxxxxxxxxxx/DPM/dpMatchSafModulePlugin:
dialstring=NULL, saf_enabled=0, saf_dndb_lookup=0, dp_result=-1
Jan 30 14:21:05.115: //2523/95A7BAC386E8/SIP/Info/sipSPIGetFromCalledPartyId: P-Called-Party-ID header not found
Jan 30 14:21:05.115: //2523/95A7BAC386E8/SIP/Info/sipSPIGetPeerByCalledPartyId: P-Called-Party-ID not found or parse error
Jan 30 14:21:05.115: //2523/95A7BAC386E8/SIP/Info/sipSPIGetCallConfig: No match found for P-Called-Party-ID
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpAssociateIncomingPeerCore:
Calling Number=Cisco-GW, Called Number=, Voice-Interface=0x0,
Timeout=TRUE, Peer Encap Type=ENCAP_VOIP, Peer Search Type=PEER_TYPE_VOICE,
Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_VIA_URI; URI=sip:192.168.1.242:5060
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_REQUEST_URI; URI=sip:cisco@192.168.1.254:5060
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_TO_URI; URI=sip:cisco@192.168.1.254
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_FROM_URI; URI=sip:Cisco-GW@192.168.1.242
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ANSWER; Calling Number=Cisco-GW
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=Cisco-GWT
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ORIGINATE; Calling Number=Cisco-GW
Jan 30 14:21:05.115: //-1/95A7BAC386E8/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:05.119: //-1/95A7BAC386E8/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=Cisco-GWT
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:05.119: //-1/95A7BAC386E8/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:05.119: //-1/95A7BAC386E8/DPM/dpAssociateIncomingPeerCore:
Result=NO_MATCH(-1) After All Match Rules Attempt
Jan 30 14:21:05.119: //-1/95A7BAC386E8/DPM/dpMatchSafModulePlugin:
dialstring=NULL, saf_enabled=0, saf_dndb_lookup=0, dp_result=-1
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPICheckReliableProvStringtag: Unable to access supported header values
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPIGetCallConfig: Media Antitrombone disabled
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPISetMediaFlowMode: Storing the configured mode as FLOW-THROUGH
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPISetMediaFlowMode: xcoder high-density disabled
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPISetMediaFlowMode: Flow Mode set to FLOW_THROUGH
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPIGetCallConfig: Non dial peer leg - using RTP Supported Codecs
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 18
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 0
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 8
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 9
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 4
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 2
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 15
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 255
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPIGetModemInfoPerCall: peer_callID=0
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPISetOverlapConfiguration: Overlap signaling: FALSE: Endpt: SIP Trunk
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPIValidateStreamAddrType: stream:1, Mode : 1
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 192.168.1.254
Jan 30 14:21:05.119: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_OPTIONS_RESP
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sact_idle_new_message_options: ccsip_api_options_ind returned: SIP_SUCCESS
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/State/sipSPIChangeState: 0x2B763340 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_NONE)
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPIUaddCcbToUASReqTable: ****Adding to UAS Request table.
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x2B763340 key=bccf2289-9947-44a9-916b-bcd67641a3b3cisco
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 9DB to table
Jan 30 14:21:05.119: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 38
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Info/sipSPISendOptionsResponse: Associated container=0x320F5A18 to Options Response
Jan 30 14:21:05.119: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 56
Jan 30 14:21:05.119: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 61
Jan 30 14:21:05.119: //2523/95A7BAC386E8/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.242:5060;rport;branch=z9hG4bKPjbb6831cc-9047-42ac-88f5-caa8b0cc08b5
From: <sip:Cisco-GW@192.168.1.242>;tag=463bc7a8-c52f-42d2-826b-a542273b98cb
To: <sip:cisco@192.168.1.254>;tag=1037404-12B5
Date: Thu, 30 Jan 2020 14:21:05 GMT
Call-ID: bccf2289-9947-44a9-916b-bcd67641a3b3
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 49156 OPTIONS
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Accept: application/sdp
Supported: 100rel,timer,resource-priority,replaces,sdp-anat
Content-Type: application/sdp
Content-Length: 454

v=0
o=CiscoSystemsSIP-GW-UserAgent 9038 6807 IN IP4 192.168.1.254
s=SIP Call
c=IN IP4 192.168.1.254
t=0 0
m=audio 0 RTP/AVP 18 0 8 9 4 2 15
c=IN IP4 192.168.1.254
m=image 0 udptl t38
c=IN IP4 192.168.1.254
a=T38FaxVersion:0
a=T38MaxBitRate:9600
a=T38FaxFillBitRemoval:0
a=T38FaxTranscodingMMR:0
a=T38FaxTranscodingJBIG:0
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxBuffer:200
a=T38FaxMaxDatagram:320
a=T38FaxUdpEC:t38UDPRedundancy

Jan 30 14:21:07.235: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x2B77F4F0) with key=[2483] to table
Jan 30 14:21:07.235: //-1/000000000000/SIP/Info/ccsip_offer_ans_init:
Jan 30 14:21:07.235: //-1/000000000000/SIP/Info/ccsip_iwf_init:
Jan 30 14:21:07.235: //-1/000000000000/SIP/Info/ccsip_ipip_media_service_init:
Jan 30 14:21:07.235: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry...
Jan 30 14:21:07.235: //-1/000000000000/SIP/Info/ccsipRegisterSetTargetInfo: p2p mode with Registrar Server = ipv4:192.168.1.242
Jan 30 14:21:07.235: //-1/000000000000/SIP/Info/ccsipRegisterSetTargetInfo: Parsing The Registrar Address
Jan 30 14:21:07.235: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetOutboundHostAndDestHostPrivate: CCSIP: target_host : 192.168.1.242 target_port : 5060

Jan 30 14:21:07.235: //-1/000000000000/SIP/Info/sipSPIValidateAndCopyOutboundHost: CCSIP: copy target_host to outbound_host
Jan 30 14:21:07.235: //-1/000000000000/SIP/Info/sipSPIOutboundProxyReuse: Do not reuse Outbound Proxy IP adress and Port
Jan 30 14:21:07.235: //-1/000000000000/SIP/State/sipSPIChangeState: 0x2B77F4F0 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
Jan 30 14:21:07.235: //-1/000000000000/SIP/Info/ccsip_spi_registrar_add_expires_header: Inside ccsip_spi_registrar_add_expires_header for Expires
Jan 30 14:21:07.235: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_OUTBOUND_REGISTER
Jan 30 14:21:07.235: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIIncrementOverloadCount: Local 1 Global 1
Jan 30 14:21:07.235: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x2B752570) with key=[2484] to table
Jan 30 14:21:07.235: //-1/000000000000/SIP/Info/ccsip_offer_ans_init:
Jan 30 14:21:07.235: //-1/000000000000/SIP/Info/ccsip_iwf_init:
Jan 30 14:21:07.235: //-1/000000000000/SIP/Info/ccsip_ipip_media_service_init:
Jan 30 14:21:07.235: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry...
Jan 30 14:21:07.235: //-1/000000000000/SIP/Info/ccsipRegisterSetTargetInfo: p2p mode with Registrar Server = ipv4:192.168.1.242
Jan 30 14:21:07.235: //-1/000000000000/SIP/Info/ccsipRegisterSetTargetInfo: Parsing The Registrar Address
Jan 30 14:21:07.235: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetOutboundHostAndDestHostPrivate: CCSIP: target_host : 192.168.1.242 target_port : 5060

Jan 30 14:21:07.235: //-1/000000000000/SIP/Info/sipSPIValidateAndCopyOutboundHost: CCSIP: copy target_host to outbound_host
Jan 30 14:21:07.235: //-1/000000000000/SIP/Info/sipSPIOutboundProxyReuse: Do not reuse Outbound Proxy IP adress and Port
Jan 30 14:21:07.235: //-1/000000000000/SIP/State/sipSPIChangeState: 0x2B752570 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
Jan 30 14:21:07.235: //-1/000000000000/SIP/Info/ccsip_spi_registrar_add_expires_header: Inside ccsip_spi_registrar_add_expires_header for Expires
Jan 30 14:21:07.235: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_OUTBOUND_REGISTER
Jan 30 14:21:07.235: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIIncrementOverloadCount: Local 1 Global 2
Jan 30 14:21:07.235: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 40
Jan 30 14:21:07.235: //-1/000000000000/SIP/Info/act_idle_outgoing_register: In act_idle_outgoing_register

Jan 30 14:21:07.235: //2524/000000000000/SIP/Info/act_idle_outgoing_register: Send REGISTER to 192.168.1.242:5060

Jan 30 14:21:07.235: //2524/000000000000/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table.
Jan 30 14:21:07.235: //2524/000000000000/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x2B77F4F0 key=335B6C2B-427811EA-8005B591-EFBDCE88
Jan 30 14:21:07.235: //2524/000000000000/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 192.168.1.254
Jan 30 14:21:07.235: //2524/000000000000/SIP/Info/sipSPIPresendProcessing: Presend Processing called for 7 event
Jan 30 14:21:07.235: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB
Jan 30 14:21:07.235: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB
Jan 30 14:21:07.235: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
Jan 30 14:21:07.239: //2524/000000000000/SIP/Info/sipSPISendRegister: Associated container=0x320F4DB8 to Register
Jan 30 14:21:07.239: //2524/000000000000/SIP/State/sipSPIChangeState: 0x2B77F4F0 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE)
Jan 30 14:21:07.239: //2524/000000000000/SIP/State/sipSPIChangeState: 0x2B77F4F0 : State change from (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE)
Jan 30 14:21:07.239: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 40
Jan 30 14:21:07.239: //-1/000000000000/SIP/Info/act_idle_outgoing_register: In act_idle_outgoing_register

Jan 30 14:21:07.239: //-1/000000000000/SIP/Info/act_idle_outgoing_register: Send REGISTER to 192.168.1.242:5060

Jan 30 14:21:07.239: //-1/000000000000/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table.
Jan 30 14:21:07.239: //-1/000000000000/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x2B752570 key=336EF424-427811EA-8006B591-EFBDCE88
Jan 30 14:21:07.239: //-1/000000000000/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 192.168.1.254
Jan 30 14:21:07.239: //-1/000000000000/SIP/Info/sipSPIPresendProcessing: Presend Processing called for 7 event
Jan 30 14:21:07.239: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB
Jan 30 14:21:07.239: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB
Jan 30 14:21:07.239: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
Jan 30 14:21:07.239: //-1/000000000000/SIP/Info/sipSPISendRegister: Associated container=0x320F40A8 to Register
Jan 30 14:21:07.239: //-1/000000000000/SIP/State/sipSPIChangeState: 0x2B752570 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE)
Jan 30 14:21:07.239: //-1/000000000000/SIP/State/sipSPIChangeState: 0x2B752570 : State change from (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE)
Jan 30 14:21:07.243: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.1.242]:5060, local_address:[192.168.1.254]
Jan 30 14:21:07.243: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
Jan 30 14:21:07.243: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
OPTIONS sip:cisco@192.168.1.254:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.242:5060;rport;branch=z9hG4bKPjbb6831cc-9047-42ac-88f5-caa8b0cc08b5
From: <sip:Cisco-GW@192.168.1.242>;tag=463bc7a8-c52f-42d2-826b-a542273b98cb
To: <sip:cisco@192.168.1.254>
Contact: <sip:Cisco-GW@192.168.1.242:5060>
Call-ID: bccf2289-9947-44a9-916b-bcd67641a3b3
CSeq: 49156 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-15.0.16.42(16.4.1)
Content-Length: 0

Jan 30 14:21:07.243: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
Jan 30 14:21:07.243: //2523/95A7BAC386E8/SIP/Info/sipSPIFindCcbUASReqTable: *****CCB found in UAS Request table. ccb=0x2B763340
Jan 30 14:21:07.243: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
Jan 30 14:21:07.243: //2523/95A7BAC386E8/SIP/Info/sipSPISendOptionsResponse: Associated container=0x320F5A18 to Options Response
Jan 30 14:21:07.243: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 55
Jan 30 14:21:07.243: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 53
Jan 30 14:21:07.243: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDecrementOverloadCount: Count:Local 0 Global 1
Jan 30 14:21:07.243: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_register_reset_dns_cache: CCSIP_REGISTER:: registrar 0 DNS resolved addr reset
Jan 30 14:21:07.243: //2524/000000000000/SIP/Info/sipSPIRegPthruProcessResponse: Processing response w/ resp code == 5
Jan 30 14:21:07.243: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetRPCBFromRCB: Retreiving RCB [0x2B94683C] from RPCB [0x0]
Jan 30 14:21:07.243: //-1/xxxxxxxxxxxx/SIP/Info/ccsipRegisterStartRCBTimer: Starting timer for pattern 102 for 180 seconds
Jan 30 14:21:07.243: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[2483] removed.
Jan 30 14:21:07.243: //2524/000000000000/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table.
Jan 30 14:21:07.243: //2524/000000000000/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x2B77F4F0 key=335B6C2B-427811EA-8005B591-EFBDCE88
Jan 30 14:21:07.243: //2524/000000000000/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
Jan 30 14:21:07.243: //2524/000000000000/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
Jan 30 14:21:07.243: //2524/000000000000/SIP/Info/ccsip_offer_ans_delete:
Jan 30 14:21:07.243: //2524/000000000000/SIP/Info/ccsip_iwf_delete:
Jan 30 14:21:07.243: //2524/000000000000/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 2B77F4F0
Jan 30 14:21:07.243: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[2483]
Jan 30 14:21:07.243: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 53
Jan 30 14:21:07.243: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDecrementOverloadCount: Count:Local 0 Global 0
Jan 30 14:21:07.243: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_register_reset_dns_cache: CCSIP_REGISTER:: registrar 0 DNS resolved addr reset
Jan 30 14:21:07.243: //-1/000000000000/SIP/Info/sipSPIRegPthruProcessResponse: Processing response w/ resp code == 5
Jan 30 14:21:07.243: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetRPCBFromRCB: Retreiving RCB [0x318B3B38] from RPCB [0x0]
Jan 30 14:21:07.243: //-1/xxxxxxxxxxxx/SIP/Info/ccsipRegisterStartRCBTimer: Starting timer for pattern 103 for 180 seconds
Jan 30 14:21:07.243: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[2484] removed.
Jan 30 14:21:07.243: //-1/000000000000/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table.
Jan 30 14:21:07.243: //-1/000000000000/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x2B752570 key=336EF424-427811EA-8006B591-EFBDCE88
Jan 30 14:21:07.243: //-1/000000000000/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
Jan 30 14:21:07.243: //-1/000000000000/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
Jan 30 14:21:07.243: //-1/000000000000/SIP/Info/ccsip_offer_ans_delete:
Jan 30 14:21:07.243: //-1/000000000000/SIP/Info/ccsip_iwf_delete:
Jan 30 14:21:07.247: //2525/000000000000/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 2B752570
Jan 30 14:21:07.247: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[2484]
Jan 30 14:21:07.467: //-1/xxxxxxxxxxxx/SIP/Info/udpsock_close_connect: Socket fd: 1 closed for connid 3 with remote port: 5060
Jan 30 14:21:07.467: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 53
Jan 30 14:21:07.467: //2523/95A7BAC386E8/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 9DB
Jan 30 14:21:07.467: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[2482] removed.
Jan 30 14:21:07.467: //2523/95A7BAC386E8/SIP/Info/sipSPIUdeleteCcbFromUASReqTable: ****Deleting from UAS Request table.
Jan 30 14:21:07.467: //2523/95A7BAC386E8/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x2B763340 key=bccf2289-9947-44a9-916b-bcd67641a3b3cisco
Jan 30 14:21:07.467: //2523/95A7BAC386E8/SIP/Info/sipSPIUdeleteCcbFromUASRespTable: ****Deleting from UAS Response table.
Jan 30 14:21:07.471: //2523/95A7BAC386E8/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
Jan 30 14:21:07.471: //2523/95A7BAC386E8/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
Jan 30 14:21:07.471: //2523/95A7BAC386E8/SIP/Info/ccsip_offer_ans_delete:
Jan 30 14:21:07.471: //2523/95A7BAC386E8/SIP/Info/ccsip_iwf_delete:
Jan 30 14:21:07.471: //2523/95A7BAC386E8/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 2B763340
Jan 30 14:21:07.471: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[2482]
Jan 30 14:21:11.115: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.1.242]:5060, local_address:[192.168.1.254]
Jan 30 14:21:11.115: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
Jan 30 14:21:11.115: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
OPTIONS sip:cisco@192.168.1.254:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.242:5060;rport;branch=z9hG4bKPjbb6831cc-9047-42ac-88f5-caa8b0cc08b5
From: <sip:Cisco-GW@192.168.1.242>;tag=463bc7a8-c52f-42d2-826b-a542273b98cb
To: <sip:cisco@192.168.1.254>
Contact: <sip:Cisco-GW@192.168.1.242:5060>
Call-ID: bccf2289-9947-44a9-916b-bcd67641a3b3
CSeq: 49156 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-15.0.16.42(16.4.1)
Content-Length: 0

Jan 30 14:21:11.115: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
Jan 30 14:21:11.115: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x2B763340) with key=[2485] to table
Jan 30 14:21:11.115: //-1/000000000000/SIP/Info/ccsip_offer_ans_init:
Jan 30 14:21:11.115: //-1/000000000000/SIP/Info/ccsip_iwf_init:
Jan 30 14:21:11.115: //-1/000000000000/SIP/Info/ccsip_ipip_media_service_init:
Jan 30 14:21:11.115: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry...
Jan 30 14:21:11.115: //-1/000000000000/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 192.168.1.254
Jan 30 14:21:11.115: //-1/993B41C386E9/SIP/State/sipSPIChangeState: 0x2B763340 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
Jan 30 14:21:11.115: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
Jan 30 14:21:11.115: //2526/993B41C386E9/SIP/Info/ccsipInitPldCallingInfo: non-numeric calling number: Cisco-GW
Jan 30 14:21:11.115: //2526/993B41C386E9/SIP/Info/sipSPIGetViaHostInURLFormat: VIA URL:sip:192.168.1.242:5060, Host:192.168.1.242
Jan 30 14:21:11.115: //2526/993B41C386E9/SIP/Info/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: : Cisco-GW
Jan 30 14:21:11.115: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Calling Number=Cisco-GW, Called Number=, Voice-Interface=0x0,
Timeout=TRUE, Peer Encap Type=ENCAP_VOIP, Peer Search Type=PEER_TYPE_VOICE,
Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:11.115: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ANSWER; Calling Number=Cisco-GW
Jan 30 14:21:11.115: //-1/xxxxxxxxxxxx/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:11.115: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=Cisco-GWT
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:11.115: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:11.115: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ORIGINATE; Calling Number=Cisco-GW
Jan 30 14:21:11.115: //-1/xxxxxxxxxxxx/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:11.115: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=Cisco-GWT
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:11.115: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:11.115: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Result=NO_MATCH(-1) After All Match Rules Attempt
Jan 30 14:21:11.115: //-1/xxxxxxxxxxxx/DPM/dpMatchSafModulePlugin:
dialstring=NULL, saf_enabled=0, saf_dndb_lookup=0, dp_result=-1
Jan 30 14:21:11.115: //2526/993B41C386E9/SIP/Info/sipSPIGetFromCalledPartyId: P-Called-Party-ID header not found
Jan 30 14:21:11.115: //2526/993B41C386E9/SIP/Info/sipSPIGetPeerByCalledPartyId: P-Called-Party-ID not found or parse error
Jan 30 14:21:11.115: //2526/993B41C386E9/SIP/Info/sipSPIGetCallConfig: No match found for P-Called-Party-ID
Jan 30 14:21:11.115: //-1/993B41C386E9/DPM/dpAssociateIncomingPeerCore:
Calling Number=Cisco-GW, Called Number=, Voice-Interface=0x0,
Timeout=TRUE, Peer Encap Type=ENCAP_VOIP, Peer Search Type=PEER_TYPE_VOICE,
Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:11.115: //-1/993B41C386E9/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_VIA_URI; URI=sip:192.168.1.242:5060
Jan 30 14:21:11.115: //-1/993B41C386E9/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:11.115: //-1/993B41C386E9/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:11.115: //-1/993B41C386E9/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:11.115: //-1/993B41C386E9/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_REQUEST_URI; URI=sip:cisco@192.168.1.254:5060
Jan 30 14:21:11.115: //-1/993B41C386E9/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:11.115: //-1/993B41C386E9/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:11.115: //-1/993B41C386E9/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:11.115: //-1/993B41C386E9/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_TO_URI; URI=sip:cisco@192.168.1.254
Jan 30 14:21:11.115: //-1/993B41C386E9/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:11.115: //-1/993B41C386E9/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:11.115: //-1/993B41C386E9/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:11.115: //-1/993B41C386E9/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_FROM_URI; URI=sip:Cisco-GW@192.168.1.242
Jan 30 14:21:11.115: //-1/993B41C386E9/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:11.115: //-1/993B41C386E9/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:11.119: //-1/993B41C386E9/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:11.119: //-1/993B41C386E9/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ANSWER; Calling Number=Cisco-GW
Jan 30 14:21:11.119: //-1/993B41C386E9/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:11.119: //-1/993B41C386E9/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=Cisco-GWT
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:11.119: //-1/993B41C386E9/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:11.119: //-1/993B41C386E9/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ORIGINATE; Calling Number=Cisco-GW
Jan 30 14:21:11.119: //-1/993B41C386E9/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:11.119: //-1/993B41C386E9/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=Cisco-GWT
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:11.119: //-1/993B41C386E9/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:11.119: //-1/993B41C386E9/DPM/dpAssociateIncomingPeerCore:
Result=NO_MATCH(-1) After All Match Rules Attempt
Jan 30 14:21:11.119: //-1/993B41C386E9/DPM/dpMatchSafModulePlugin:
dialstring=NULL, saf_enabled=0, saf_dndb_lookup=0, dp_result=-1
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPICheckReliableProvStringtag: Unable to access supported header values
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPIGetCallConfig: Media Antitrombone disabled
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPISetMediaFlowMode: Storing the configured mode as FLOW-THROUGH
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPISetMediaFlowMode: xcoder high-density disabled
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPISetMediaFlowMode: Flow Mode set to FLOW_THROUGH
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPIGetCallConfig: Non dial peer leg - using RTP Supported Codecs
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 18
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 0
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 8
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 9
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 4
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 2
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 15
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 255
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPIGetModemInfoPerCall: peer_callID=0
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPISetOverlapConfiguration: Overlap signaling: FALSE: Endpt: SIP Trunk
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPIValidateStreamAddrType: stream:1, Mode : 1
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 192.168.1.254
Jan 30 14:21:11.119: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_OPTIONS_RESP
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sact_idle_new_message_options: ccsip_api_options_ind returned: SIP_SUCCESS
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/State/sipSPIChangeState: 0x2B763340 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_NONE)
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPIUaddCcbToUASReqTable: ****Adding to UAS Request table.
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x2B763340 key=bccf2289-9947-44a9-916b-bcd67641a3b3cisco
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 9DE to table
Jan 30 14:21:11.119: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 38
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Info/sipSPISendOptionsResponse: Associated container=0x320F43C0 to Options Response
Jan 30 14:21:11.119: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 56
Jan 30 14:21:11.119: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 61
Jan 30 14:21:11.119: //2526/993B41C386E9/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.242:5060;rport;branch=z9hG4bKPjbb6831cc-9047-42ac-88f5-caa8b0cc08b5
From: <sip:Cisco-GW@192.168.1.242>;tag=463bc7a8-c52f-42d2-826b-a542273b98cb
To: <sip:cisco@192.168.1.254>;tag=1038B74-F02
Date: Thu, 30 Jan 2020 14:21:11 GMT
Call-ID: bccf2289-9947-44a9-916b-bcd67641a3b3
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 49156 OPTIONS
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Accept: application/sdp
Supported: 100rel,timer,resource-priority,replaces,sdp-anat
Content-Type: application/sdp
Content-Length: 454

v=0
o=CiscoSystemsSIP-GW-UserAgent 7368 1991 IN IP4 192.168.1.254
s=SIP Call
c=IN IP4 192.168.1.254
t=0 0
m=audio 0 RTP/AVP 18 0 8 9 4 2 15
c=IN IP4 192.168.1.254
m=image 0 udptl t38
c=IN IP4 192.168.1.254
a=T38FaxVersion:0
a=T38MaxBitRate:9600
a=T38FaxFillBitRemoval:0
a=T38FaxTranscodingMMR:0
a=T38FaxTranscodingJBIG:0
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxBuffer:200
a=T38FaxMaxDatagram:320
a=T38FaxUdpEC:t38UDPRedundancy

VOIP-R#
VOIP-R#
VOIP-R#
Jan 30 14:21:15.115: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.1.242]:5060, local_address:[192.168.1.254]
Jan 30 14:21:15.115: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
Jan 30 14:21:15.115: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
OPTIONS sip:cisco@192.168.1.254:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.242:5060;rport;branch=z9hG4bKPjbb6831cc-9047-42ac-88f5-caa8b0cc08b5
From: <sip:Cisco-GW@192.168.1.242>;tag=463bc7a8-c52f-42d2-826b-a542273b98cb
To: <sip:cisco@192.168.1.254>
Contact: <sip:Cisco-GW@192.168.1.242:5060>
Call-ID: bccf2289-9947-44a9-916b-bcd67641a3b3
CSeq: 49156 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-15.0.16.42(16.4.1)
Content-Length: 0

Jan 30 14:21:15.115: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
Jan 30 14:21:15.115: //2526/993B41C386E9/SIP/Info/sipSPIFindCcbUASReqTable: *****CCB found in UAS Request table. ccb=0x2B763340
Jan 30 14:21:15.115: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
Jan 30 14:21:15.115: //2526/993B41C386E9/SIP/Info/sipSPISendOptionsResponse: Associated container=0x320F43C0 to Options Response
Jan 30 14:21:15.115: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 55
Jan 30 14:21:15.115: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 53
Jan 30 14:21:15.115: //2526/993B41C386E9/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 9DE
Jan 30 14:21:15.115: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[2485] removed.
Jan 30 14:21:15.115: //2526/993B41C386E9/SIP/Info/sipSPIUdeleteCcbFromUASReqTable: ****Deleting from UAS Request table.
Jan 30 14:21:15.115: //2526/993B41C386E9/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x2B763340 key=bccf2289-9947-44a9-916b-bcd67641a3b3cisco
Jan 30 14:21:15.115: //2526/993B41C386E9/SIP/Info/sipSPIUdeleteCcbFromUASRespTable: ****Deleting from UAS Response table.
Jan 30 14:21:15.115: //2526/993B41C386E9/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
Jan 30 14:21:15.115: //2526/993B41C386E9/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
Jan 30 14:21:15.115: //2526/993B41C386E9/SIP/Info/ccsip_offer_ans_delete:
Jan 30 14:21:15.115: //2526/993B41C386E9/SIP/Info/ccsip_iwf_delete:
Jan 30 14:21:15.115: //2526/993B41C386E9/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 2B763340
Jan 30 14:21:15.115: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[2485]
Jan 30 14:21:15.115: //-1/xxxxxxxxxxxx/SIP/Info/udpsock_close_connect: Socket fd: 1 closed for connid 3 with remote port: 5060
Jan 30 14:21:19.115: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.1.242]:5060, local_address:[192.168.1.254]
Jan 30 14:21:19.115: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
Jan 30 14:21:19.115: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
OPTIONS sip:cisco@192.168.1.254:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.242:5060;rport;branch=z9hG4bKPjbb6831cc-9047-42ac-88f5-caa8b0cc08b5
From: <sip:Cisco-GW@192.168.1.242>;tag=463bc7a8-c52f-42d2-826b-a542273b98cb
To: <sip:cisco@192.168.1.254>
Contact: <sip:Cisco-GW@192.168.1.242:5060>
Call-ID: bccf2289-9947-44a9-916b-bcd67641a3b3
CSeq: 49156 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-15.0.16.42(16.4.1)
Content-Length: 0

Jan 30 14:21:19.115: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
Jan 30 14:21:19.115: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x2B763340) with key=[2486] to table
Jan 30 14:21:19.115: //-1/000000000000/SIP/Info/ccsip_offer_ans_init:
Jan 30 14:21:19.115: //-1/000000000000/SIP/Info/ccsip_iwf_init:
Jan 30 14:21:19.115: //-1/000000000000/SIP/Info/ccsip_ipip_media_service_init:
Jan 30 14:21:19.115: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry...
Jan 30 14:21:19.115: //-1/000000000000/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 192.168.1.254
Jan 30 14:21:19.115: //-1/9DFFF5C386EA/SIP/State/sipSPIChangeState: 0x2B763340 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
Jan 30 14:21:19.115: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
Jan 30 14:21:19.115: //2527/9DFFF5C386EA/SIP/Info/ccsipInitPldCallingInfo: non-numeric calling number: Cisco-GW
Jan 30 14:21:19.115: //2527/9DFFF5C386EA/SIP/Info/sipSPIGetViaHostInURLFormat: VIA URL:sip:192.168.1.242:5060, Host:192.168.1.242
Jan 30 14:21:19.115: //2527/9DFFF5C386EA/SIP/Info/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: : Cisco-GW
Jan 30 14:21:19.115: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Calling Number=Cisco-GW, Called Number=, Voice-Interface=0x0,
Timeout=TRUE, Peer Encap Type=ENCAP_VOIP, Peer Search Type=PEER_TYPE_VOICE,
Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:19.115: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ANSWER; Calling Number=Cisco-GW
Jan 30 14:21:19.115: //-1/xxxxxxxxxxxx/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:19.115: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=Cisco-GWT
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:19.115: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:19.115: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ORIGINATE; Calling Number=Cisco-GW
Jan 30 14:21:19.115: //-1/xxxxxxxxxxxx/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:19.115: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=Cisco-GWT
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:19.115: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:19.115: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Result=NO_MATCH(-1) After All Match Rules Attempt
Jan 30 14:21:19.115: //-1/xxxxxxxxxxxx/DPM/dpMatchSafModulePlugin:
dialstring=NULL, saf_enabled=0, saf_dndb_lookup=0, dp_result=-1
Jan 30 14:21:19.115: //2527/9DFFF5C386EA/SIP/Info/sipSPIGetFromCalledPartyId: P-Called-Party-ID header not found
Jan 30 14:21:19.115: //2527/9DFFF5C386EA/SIP/Info/sipSPIGetPeerByCalledPartyId: P-Called-Party-ID not found or parse error
Jan 30 14:21:19.115: //2527/9DFFF5C386EA/SIP/Info/sipSPIGetCallConfig: No match found for P-Called-Party-ID
Jan 30 14:21:19.115: //-1/9DFFF5C386EA/DPM/dpAssociateIncomingPeerCore:
Calling Number=Cisco-GW, Called Number=, Voice-Interface=0x0,
Timeout=TRUE, Peer Encap Type=ENCAP_VOIP, Peer Search Type=PEER_TYPE_VOICE,
Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:19.115: //-1/9DFFF5C386EA/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_VIA_URI; URI=sip:192.168.1.242:5060
Jan 30 14:21:19.115: //-1/9DFFF5C386EA/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:19.115: //-1/9DFFF5C386EA/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:19.115: //-1/9DFFF5C386EA/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:19.115: //-1/9DFFF5C386EA/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_REQUEST_URI; URI=sip:cisco@192.168.1.254:5060
Jan 30 14:21:19.115: //-1/9DFFF5C386EA/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:19.115: //-1/9DFFF5C386EA/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:19.115: //-1/9DFFF5C386EA/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:19.115: //-1/9DFFF5C386EA/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_TO_URI; URI=sip:cisco@192.168.1.254
Jan 30 14:21:19.115: //-1/9DFFF5C386EA/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:19.115: //-1/9DFFF5C386EA/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:19.115: //-1/9DFFF5C386EA/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:19.115: //-1/9DFFF5C386EA/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_FROM_URI; URI=sip:Cisco-GW@192.168.1.242
Jan 30 14:21:19.119: //-1/9DFFF5C386EA/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:19.119: //-1/9DFFF5C386EA/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:19.119: //-1/9DFFF5C386EA/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:19.119: //-1/9DFFF5C386EA/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ANSWER; Calling Number=Cisco-GW
Jan 30 14:21:19.119: //-1/9DFFF5C386EA/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:19.119: //-1/9DFFF5C386EA/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=Cisco-GWT
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:19.119: //-1/9DFFF5C386EA/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:19.119: //-1/9DFFF5C386EA/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ORIGINATE; Calling Number=Cisco-GW
Jan 30 14:21:19.119: //-1/9DFFF5C386EA/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jan 30 14:21:19.119: //-1/9DFFF5C386EA/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=Cisco-GWT
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jan 30 14:21:19.119: //-1/9DFFF5C386EA/DPM/dpMatchCore:
Result=-1
Jan 30 14:21:19.119: //-1/9DFFF5C386EA/DPM/dpAssociateIncomingPeerCore:
Result=NO_MATCH(-1) After All Match Rules Attempt
Jan 30 14:21:19.119: //-1/9DFFF5C386EA/DPM/dpMatchSafModulePlugin:
dialstring=NULL, saf_enabled=0, saf_dndb_lookup=0, dp_result=-1
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPICheckReliableProvStringtag: Unable to access supported header values
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPIGetCallConfig: Media Antitrombone disabled
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPISetMediaFlowMode: Storing the configured mode as FLOW-THROUGH
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPISetMediaFlowMode: xcoder high-density disabled
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPISetMediaFlowMode: Flow Mode set to FLOW_THROUGH
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPIGetCallConfig: Non dial peer leg - using RTP Supported Codecs
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 18
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 0
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 8
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 9
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 4
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 2
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 15
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 255
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPIGetModemInfoPerCall: peer_callID=0
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPISetOverlapConfiguration: Overlap signaling: FALSE: Endpt: SIP Trunk
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPIValidateStreamAddrType: stream:1, Mode : 1
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 192.168.1.254
Jan 30 14:21:19.119: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_OPTIONS_RESP
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sact_idle_new_message_options: ccsip_api_options_ind returned: SIP_SUCCESS
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/State/sipSPIChangeState: 0x2B763340 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_NONE)
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPIUaddCcbToUASReqTable: ****Adding to UAS Request table.
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x2B763340 key=bccf2289-9947-44a9-916b-bcd67641a3b3cisco
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 9DF to table
Jan 30 14:21:19.119: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 38
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Info/sipSPISendOptionsResponse: Associated container=0x320F41B0 to Options Response
Jan 30 14:21:19.119: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 56
Jan 30 14:21:19.119: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 61
Jan 30 14:21:19.119: //2527/9DFFF5C386EA/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.242:5060;rport;branch=z9hG4bKPjbb6831cc-9047-42ac-88f5-caa8b0cc08b5
From: <sip:Cisco-GW@192.168.1.242>;tag=463bc7a8-c52f-42d2-826b-a542273b98cb
To: <sip:cisco@192.168.1.254>;tag=103AAB4-21FB
Date: Thu, 30 Jan 2020 14:21:19 GMT
Call-ID: bccf2289-9947-44a9-916b-bcd67641a3b3
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 49156 OPTIONS
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Accept: application/sdp
Supported: 100rel,timer,resource-priority,replaces,sdp-anat
Content-Type: application/sdp
Content-Length: 454

v=0
o=CiscoSystemsSIP-GW-UserAgent 3634 8899 IN IP4 192.168.1.254
s=SIP Call
c=IN IP4 192.168.1.254
t=0 0
m=audio 0 RTP/AVP 18 0 8 9 4 2 15
c=IN IP4 192.168.1.254
m=image 0 udptl t38
c=IN IP4 192.168.1.254
a=T38FaxVersion:0
a=T38MaxBitRate:9600
a=T38FaxFillBitRemoval:0
a=T38FaxTranscodingMMR:0
a=T38FaxTranscodingJBIG:0
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxBuffer:200
a=T38FaxMaxDatagram:320
a=T38FaxUdpEC:t38UDPRedundancy

VOIP-R#
VOIP-R#u
Jan 30 14:21:23.111: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.1.242]:5060, local_address:[192.168.1.254]
Jan 30 14:21:23.115: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
Jan 30 14:21:23.115: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
OPTIONS sip:cisco@192.168.1.254:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.242:5060;rport;branch=z9hG4bKPjbb6831cc-9047-42ac-88f5-caa8b0cc08b5
From: <sip:Cisco-GW@192.168.1.242>;tag=463bc7a8-c52f-42d2-826b-a542273b98cb
To: <sip:cisco@192.168.1.254>
Contact: <sip:Cisco-GW@192.168.1.242:5060>
Call-ID: bccf2289-9947-44a9-916b-bcd67641a3b3
CSeq: 49156 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-15.0.16.42(16.4.1)
Content-Length: 0

Jan 30 14:21:23.115: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
Jan 30 14:21:23.115: //2527/9DFFF5C386EA/SIP/Info/sipSPIFindCcbUASReqTable: *****CCB found in UAS Request table. ccb=0x2B763340
Jan 30 14:21:23.115: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
Jan 30 14:21:23.115: //2527/9DFFF5C386EA/SIP/Info/sipSPISendOptionsResponse: Associated container=0x320F41B0 to Options Response
Jan 30 14:21:23.115: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 55
Jan 30 14:21:23.115: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 53
Jan 30 14:21:23.115: //2527/9DFFF5C386EA/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 9DF
Jan 30 14:21:23.115: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[2486] removed.
Jan 30 14:21:23.115: //2527/9DFFF5C386EA/SIP/Info/sipSPIUdeleteCcbFromUASReqTable: ****Deleting from UAS Request table.
Jan 30 14:21:23.115: //2527/9DFFF5C386EA/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x2B763340 key=bccf2289-9947-44a9-916b-bcd67641a3b3cisco
Jan 30 14:21:23.115: //2527/9DFFF5C386EA/SIP/Info/sipSPIUdeleteCcbFromUASRespTable: ****Deleting from UAS Response table.
Jan 30 14:21:23.115: //2527/9DFFF5C386EA/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'dn all
Jan 30 14:21:23.115: //2527/9DFFF5C386EA/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
Jan 30 14:21:23.115: //2527/9DFFF5C386EA/SIP/Info/ccsip_offer_ans_delete:
Jan 30 14:21:23.115: //2527/9DFFF5C386EA/SIP/Info/ccsip_iwf_delete:
Jan 30 14:21:23.115: //2527/9DFFF5C386EA/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 2B763340
Jan 30 14:21:23.115: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[2486]
Jan 30 14:21:23.115: //-1/xxxxxxxxxxxx/SIP/Info/udpsock_close_connect: Socket fd: 1 closed for connid 3 with remote port: 5060

regards

[Muhammad Awais Khan]

Can you share output for 'show voice port summary'?

Also you cannot make incoming call or call receive and you cannot pickup?

[KENNEDY BIZUAYEHU TADEGE]

Hi Muhamad,

Also you cannot make incoming call or call receive and you cannot pickup? Yes, i can't

below is the output for show voice port summary

VOIP-R#show voice port summary
IN OUT
PORT CH SIG-TYPE ADMIN OPER STATUS STATUS EC
=============== == ============ ===== ==== ======== ======== ==
0/0/0 -- fxo-ls up dorm idle on-hook y
0/0/1 -- fxo-ls up dorm idle on-hook y
0/0/2 -- fxo-ls up dorm idle on-hook y
0/0/3 -- fxo-ls up dorm idle on-hook y
0/2/0:15 01 isdn-voice up down none none y
0/2/0:15 02 isdn-voice up down none none y
0/2/0:15 03 isdn-voice up down none none y
0/2/0:15 04 isdn-voice up down none none y
0/2/0:15 05 isdn-voice up down none none y
0/2/0:15 06 isdn-voice up down none none y
0/2/0:15 07 isdn-voice up down none none y
0/2/0:15 08 isdn-voice up down none none y
0/2/0:15 09 isdn-voice up down none none y
0/2/0:15 10 isdn-voice up down none none y
0/2/0:15 11 isdn-voice up down none none y
0/2/0:15 12 isdn-voice up down none none y
0/2/0:15 13 isdn-voice up down none none y
0/2/0:15 14 isdn-voice up down none none y
0/2/0:15 15 isdn-voice up down none none y
0/1/0 -- fxo-ls up dorm idle on-hook y
0/1/1 -- fxo-ls up dorm idle on-hook y
0/1/2 -- fxo-ls up dorm idle on-hook y
0/1/3 -- fxo-ls up dorm idle on-hook y
50/0/1 1 efxs up up on-hook idle y
50/0/1 2 efxs up up on-hook idle y
50/0/2 1 efxs up up on-hook idle y
50/0/2 2 efxs up up on-hook idle y
50/0/3 1 efxs up up on-hook idle y
50/0/3 2 efxs up up on-hook idle y
50/0/4 1 efxs up up on-hook idle y
50/0/4 2 efxs up up on-hook idle y
50/0/10 1 efxs up up on-hook idle y
50/0/10 2 efxs up up on-hook idle y
50/0/11 1 efxs up up on-hook idle y
50/0/11 2 efxs up up on-hook idle y

PWR FAILOVER PORT PSTN FAILOVER PORT
================= ==================

[Muhammad Awais Khan]

Voice ports looks good. Can you share below output for incomming and outgoing both? I would suggest you to take the logs in notepad and attach in the reply.

Debug voice ccapi inout

debug voice dial-peer inout

Also, share your configuration after you did modification.

[KENNEDY BIZUAYEHU TADEGE]

Hi Muhamad,

I tried to make both outgoing and incoming calls to and from pstn but i got nothing on the debugs, on every call trial the FXO ports goes busy. Apologies for not attaching the notepad (The contents of the attachment doesn't match its file type).

=~=~=~=~=~=~=~=~=~=~=~= PuTTY log 2020.01.31 10:37:36 =~=~=~=~=~=~=~=~=~=~=~=
login as: symbol
Using keyboard-interactive authentication.
Password:

VOIP-R#Debug voice ccapi inout
voip ccapi inout debugging is on
VOIP-R#debug voice dial-peer inout
^
% Invalid input detected at '^' marker.

VOIP-R#debug voice dial-peer inoutpeer inout 
voip dialpeer inout debugging is on
VOIP-R#sh voice port sum
IN OUT
PORT CH SIG-TYPE ADMIN OPER STATUS STATUS EC
=============== == ============ ===== ==== ======== ======== ==
0/0/0 -- fxo-ls up up idle off-hook y
0/0/1 -- fxo-ls up dorm idle on-hook y
0/0/2 -- fxo-ls up dorm idle on-hook y
0/0/3 -- fxo-ls up dorm idle on-hook y
0/2/0:15 01 isdn-voice up down none none y
0/2/0:15 02 isdn-voice up down none none y
0/2/0:15 03 isdn-voice up down none none y
0/2/0:15 04 isdn-voice up down none none y
0/2/0:15 05 isdn-voice up down none none y
0/2/0:15 06 isdn-voice up down none none y
0/2/0:15 07 isdn-voice up down none none y
0/2/0:15 08 isdn-voice up down none none y
0/2/0:15 09 isdn-voice up down none none y
0/2/0:15 10 isdn-voice up down none none y
0/2/0:15 11 isdn-voice up down none none y
0/2/0:15 12 isdn-voice up down none none y
0/2/0:15 13 isdn-voice up down none none y
0/2/0:15 14 isdn-voice up down none none y
0/2/0:15 15 isdn-voice up down none none y
0/1/0 -- fxo-ls up dorm idle on-hook y
0/1/1 -- fxo-ls up up idle off-hook y
--More--  0/1/2 -- fxo-ls up dorm idle on-hook y
0/1/3 -- fxo-ls up dorm idle on-hook y
--More--  50/0/1 1 efxs up up on-hook idle y
50/0/1 2 efxs up up on-hook idle y
50/0/2 1 efxs up up on-hook idle y
50/0/2 2 efxs up up on-hook idle y
50/0/3 1 efxs up up on-hook idle y
50/0/3 2 efxs up up on-hook idle y
50/0/4 1 efxs up up on-hook idle y
50/0/4 2 efxs up up on-hook idle y
50/0/10 1 efxs up up on-hook idle y
50/0/10 2 efxs up up on-hook idle y
50/0/11 1 efxs up up on-hook idle y
50/0/11 2 efxs up up on-hook idle y

PWR FAILOVER PORT PSTN FAILOVER PORT
================= ==================

VOIP-R#debug ccsip states
SIP Call states tracing is enabled
VOIP-R#sh voice port sum
IN OUT
PORT CH SIG-TYPE ADMIN OPER STATUS STATUS EC
=============== == ============ ===== ==== ======== ======== ==
0/0/0 -- fxo-ls up up idle off-hook y
0/0/1 -- fxo-ls up dorm idle on-hook y
0/0/2 -- fxo-ls up up idle off-hook y
0/0/3 -- fxo-ls up dorm idle on-hook y
0/2/0:15 01 isdn-voice up down none none y
0/2/0:15 02 isdn-voice up down none none y
0/2/0:15 03 isdn-voice up down none none y
0/2/0:15 04 isdn-voice up down none none y
0/2/0:15 05 isdn-voice up down none none y
0/2/0:15 06 isdn-voice up down none none y
0/2/0:15 07 isdn-voice up down none none y
0/2/0:15 08 isdn-voice up down none none y
0/2/0:15 09 isdn-voice up down none none y
0/2/0:15 10 isdn-voice up down none none y
0/2/0:15 11 isdn-voice up down none none y
0/2/0:15 12 isdn-voice up down none none y
0/2/0:15 13 isdn-voice up down none none y
0/2/0:15 14 isdn-voice up down none none y
0/2/0:15 15 isdn-voice up down none none y
0/1/0 -- fxo-ls up up idle off-hook y
0/1/1 -- fxo-ls up up idle off-hook y
--More--  0/1/2 -- fxo-ls up up idle off-hook y
0/1/3 -- fxo-ls up up idle off-hook y
--More--  50/0/1 1 efxs up up on-hook idle y
50/0/1 2 efxs up up on-hook idle y
--More--  
VOIP-R#
VOIP-R#
VOIP-R#
VOIP-R#sh run
Building configuration...

Current configuration : 6531 bytes
!
! No configuration change since last restart
version 15.1
service timestamps debug datetime msec
service timestamps log datetime msec
no service password-encryption
!
hostname VOIP-R
!
boot-start-marker
boot-end-marker
!
!
card type e1 0 2
!
no aaa new-model
network-clock-participate wic 2
!
no ipv6 cef
ip source-route
ip cef
!
--More--  !
!
!
!
multilink bundle-name authenticated
!
!
!
!
isdn switch-type primary-net5
!
crypto pki token default removal timeout 0
!
crypto pki trustpoint TP-self-signed-3072723400
enrollment selfsigned
subject-name cn=IOS-Self-Signed-Certificate-3072723400
revocation-check none
rsakeypair TP-self-signed-3072723400
!
!
crypto pki certificate chain TP-self-signed-3072723400
certificate self-signed 01
3082022B 30820194 A0030201 02020101 300D0609 2A864886 F70D0101 05050030
31312F30 2D060355 04031326 494F532D 53656C66 2D536967 6E65642D 43657274
--More--   69666963 6174652D 33303732 37323334 3030301E 170D3139 31303131 31303133
31315A17 0D323030 31303130 30303030 305A3031 312F302D 06035504 03132649
4F532D53 656C662D 5369676E 65642D43 65727469 66696361 74652D33 30373237
32333430 3030819F 300D0609 2A864886 F70D0101 01050003 818D0030 81890281
8100E456 20ECE1EF 81AC1A27 74D7248E 59BBAEF1 B81653B8 6C3DFE0C EDB94434
8DAF3C7F 672FC346 E65E08F2 A6A726D1 4C7885E9 57610A00 A95AFB2F F8911DA4
66129BCF 755483F3 DB4B6642 42D4A71F 5DFF1A4F 4934B941 EABB3F5F 53661A62
1BF12507 521C3189 10E1FE60 D9FC7730 AF3EC617 73FF3E64 3707007C 1C17DF8D
FB510203 010001A3 53305130 0F060355 1D130101 FF040530 030101FF 301F0603
551D2304 18301680 14CAE988 5D3B9690 4B17CEBE 0A189B3B AA9940BA 52301D06
03551D0E 04160414 CAE9885D 3B96904B 17CEBE0A 189B3BAA 9940BA52 300D0609
2A864886 F70D0101 05050003 8181003A CC431B01 BACD51DA CD60BB6C C9DF42F4
E3191E44 6347CAA7 11355E75 E935DF0C 7B0D7DD0 D5F89BE0 FDA367E6 C38F211F
8A940CAC FAF0878F 72C126DE 96AD1154 D867380B ED242377 C0DA2594 E3F6CB8F
BC6B26F8 8E8DC4BD C89EB281 D057E72B 5025A2E4 A420D09B 1B893A66 64261212
6AB156A5 5F655E3F 0DAC0F37 5D22F2
quit
voice-card 0
dspfarm
dsp services dspfarm
!
!
!
voice service voip
--More--   allow-connections h323 to h323
allow-connections h323 to sip
allow-connections sip to h323
allow-connections sip to sip
redirect ip2ip
signaling forward unconditional
fax protocol t38 version 0 ls-redundancy 0 hs-redundancy 0 fallback none
sip
bind control source-interface GigabitEthernet0/0
bind media source-interface GigabitEthernet0/0
!
!
!
!
!
license udi pid CISCO2901/K9 sn FCZ163020WV
hw-module pvdm 0/0
!
hw-module pvdm 0/1
!
!
!
username symbol privilege 15 password 0 passwd
username admin password 0 admin
--More--  !
redundancy
!
!
controller E1 0/2/0
framing NO-CRC4
pri-group timeslots 1-16
!
!
!
!
!
interface Loopback0
ip address 192.168.10.10 255.255.255.0
!
interface Embedded-Service-Engine0/0
no ip address
shutdown
!
interface GigabitEthernet0/0
ip address 192.168.1.254 255.255.255.0
duplex auto
speed auto
!
--More--  interface GigabitEthernet0/1
no ip address
shutdown
duplex auto
speed auto
!
interface Serial0/2/0:15
no ip address
encapsulation hdlc
isdn switch-type primary-net5
isdn incoming-voice voice
no cdp enable
!
ip forward-protocol nd
!
ip http server
ip http authentication local
ip http secure-server
!
ip route 0.0.0.0 0.0.0.0 192.168.1.1
!
!
!
!
--More--  control-plane
!
!
voice-port 0/0/0
connection plar opx 200
!
voice-port 0/0/1
connection plar opx 200
!
voice-port 0/0/2
connection plar opx 200
!
voice-port 0/0/3
connection plar opx 200
!
voice-port 0/2/0:15
!
voice-port 0/1/0
connection plar opx 201
!
voice-port 0/1/1
connection plar opx 201
!
voice-port 0/1/2
--More--   connection plar opx 201
!
voice-port 0/1/3
connection plar opx 201
!
ccm-manager mgcp
ccm-manager config
!
mgcp
!
mgcp profile default
!
!
dial-peer voice 2 pots
description Outside Call
destination-pattern .T
port 0/0/1
forward-digits all
!
dial-peer voice 3 pots
description Outside Call
destination-pattern .T
port 0/0/2
forward-digits all
--More--  !
dial-peer voice 200 voip
description FreePBX-Trunk
numbering-type unknown
destination-pattern 2..
session protocol sipv2
session target ipv4:192.168.1.242:5060
session transport udp
incoming called-number .T
dtmf-relay rtp-nte
codec g711ulaw
!
dial-peer voice 1 pots
description Outside Call
destination-pattern .T
port 0/0/0
forward-digits all
!
dial-peer voice 4 pots
description Outside Call
destination-pattern .T
port 0/0/3
forward-digits all
!
--More--  dial-peer voice 5 pots
description Outside Call
destination-pattern .T
port 0/1/0
forward-digits all
!
dial-peer voice 6 pots
description Outside Call
destination-pattern .T
port 0/1/1
forward-digits all
!
dial-peer voice 7 pots
description Outside Call
destination-pattern .T
port 0/1/2
forward-digits all
!
dial-peer voice 8 pots
description Outside Call
destination-pattern .T
port 0/1/3
forward-digits all
!
--More--  !
gateway
timer receive-rtp 1200
!
sip-ua
credentials username symbolcme password 7 044B0A151C3648 realm bitrix24
credentials username cisco password 7 071F205F5D1E1D realm freepbx
no remote-party-id
retry invite 3
retry response 3
retry bye 3
retry cancel 3
timers trying 1000
registrar ipv4:192.168.1.242 expires 3600
sip-server ipv4:192.168.1.242
!
!
!
gatekeeper
shutdown
!
!
telephony-service
max-ephones 35
--More--   max-dn 35
ip source-address 192.168.1.254 port 2000
max-conferences 8 gain -6
transfer-system full-consult
!
!
ephone-dn 1 dual-line
number 102
label Naod Missale (102)
description Naod Missale
name Naod Missale
!
!
ephone-dn 2 dual-line
number 103
label Tewodros Kifle (103)
description Tewodros Kifle
name Tewodros Kifle
!
!
ephone-dn 3 dual-line
number 104
label Abebe Kegne (104)
description Abebe Kegne
--More--   name Abebe Kegne
!
!
ephone-dn 4 dual-line
number 105
label Yibeltal Adinew (105)
description Yibeltal Adinew
name Yibeltal Adinew
!
!
ephone-dn 10 dual-line
number 110
label Test One (110)
description Test One
name Test One
!
!
ephone-dn 11 dual-line
number 111
label Test Two (111)
description Test Two
name Test Two
!
!
--More--  ephone 10
mac-address 54EE.75B1.B139
type CIPC
button 1:10
!
!
!
ephone 11
mac-address C83D.D4AE.16B3
type CIPC
button 1:11
!
!
!
!
line con 0
line aux 0
line 2
no activation-character
no exec
transport preferred none
transport input all
transport output pad telnet rlogin lapb-ta mop udptn v120 ssh
stopbits 1
--More--  line vty 0 4
privilege level 15
login local
transport input telnet ssh
!
scheduler allocate 20000 1000
end

VOIP-R#

regards

[KENNEDY BIZUAYEHU TADEGE]

Hi Muhamad,

Also you cannot make incoming call or call receive and you cannot pickup? Yes, Ican't 

VOIP-R#show voice port summary
IN OUT
PORT CH SIG-TYPE ADMIN OPER STATUS STATUS EC
=============== == ============ ===== ==== ======== ======== ==
0/0/0 -- fxo-ls up dorm idle on-hook y
0/0/1 -- fxo-ls up dorm idle on-hook y
0/0/2 -- fxo-ls up dorm idle on-hook y
0/0/3 -- fxo-ls up dorm idle on-hook y
0/2/0:15 01 isdn-voice up down none none y
0/2/0:15 02 isdn-voice up down none none y
0/2/0:15 03 isdn-voice up down none none y
0/2/0:15 04 isdn-voice up down none none y
0/2/0:15 05 isdn-voice up down none none y
0/2/0:15 06 isdn-voice up down none none y
0/2/0:15 07 isdn-voice up down none none y
0/2/0:15 08 isdn-voice up down none none y
0/2/0:15 09 isdn-voice up down none none y
0/2/0:15 10 isdn-voice up down none none y
0/2/0:15 11 isdn-voice up down none none y
0/2/0:15 12 isdn-voice up down none none y
0/2/0:15 13 isdn-voice up down none none y
0/2/0:15 14 isdn-voice up down none none y
0/2/0:15 15 isdn-voice up down none none y
0/1/0 -- fxo-ls up dorm idle on-hook y
0/1/1 -- fxo-ls up dorm idle on-hook y
0/1/2 -- fxo-ls up dorm idle on-hook y
0/1/3 -- fxo-ls up dorm idle on-hook y
50/0/1 1 efxs up up on-hook idle y
50/0/1 2 efxs up up on-hook idle y
50/0/2 1 efxs up up on-hook idle y
50/0/2 2 efxs up up on-hook idle y
50/0/3 1 efxs up up on-hook idle y
50/0/3 2 efxs up up on-hook idle y
50/0/4 1 efxs up up on-hook idle y
50/0/4 2 efxs up up on-hook idle y
50/0/10 1 efxs up up on-hook idle y
50/0/10 2 efxs up up on-hook idle y
50/0/11 1 efxs up up on-hook idle y
50/0/11 2 efxs up up on-hook idle y

PWR FAILOVER PORT PSTN FAILOVER PORT
================= ==================

[Muhammad Awais Khan]

Hi,

If you are using telnet/ssh to Router the  you should also enter terminal monitor in Router's exec mode.

Can you try to take.debugs after terminal monitor ?

[eliastefera]

Dear Muhammad,

Apologies for being lost, the problem was SIP signaling was blocked by the freepbx firewall and the calls were not going to the Cisco gateway and that's why there was no any debug log on the router. and its working as expected.

I really appreciate your patience n support.

Thanks again !!!!!!!!