Apr 21 14:50:57.213: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [54.171.127.192]:5060, local_address:[ - ] Apr 21 14:50:57.213: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Apr 21 14:50:57.213: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Apr 21 14:50:57.213: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: INVITE sip:+442086295370@62.133.18.252 SIP/2.0 Record-Route: From: ;tag=58203968_6772d868_32c36cbd-f873-43ec-b213-73a360cab2ad To: CSeq: 1 INVITE Max-Forwards: 60 P-Asserted-Identity: Expires: 330 Diversion: ;reason=unconditional Call-ID: 02bea03153bed387ef71c1fec1707da3@0.0.0.0 Via: SIP/2.0/UDP 54.171.127.192:5060;branch=z9hG4bKa4b8.68b062a2.0 Via: SIP/2.0/UDP 172.18.204.154:5060;rport=5060;received=172.18.204.154;branch=z9hG4bK32c36cbd-f873-43ec-b213-73a360cab2ad_6772d868_230-11839665410571672965 Contact: Allow: BYE,CANCEL,ACK,INVITE,OPTIONS User-Agent: Twilio Gateway X-Twilio-AccountSid: AC4883f7d4c5821780996cf72e2dbe4f31 Content-Type: application/sdp X-Twilio-CallSid: CA2f08ab353665c06321affc348a7ed560 Content-Length: 277 v=0 o=- 821401870 821401870 IN IP4 54.171.127.207 s=Twilio Media Gateway c=IN IP4 54.171.127.207 t=0 0 m=audio 15600 RTP/AVP 101 0 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - a=ptime:20 a=maxptime:30 a=sendrecv Apr 21 14:50:57.213: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog Apr 21 14:50:57.213: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x49C73D28) with key=[1466] to table Apr 21 14:50:57.213: //-1/000000000000/SIP/Info/ccsip_offer_ans_init: Apr 21 14:50:57.213: //-1/000000000000/SIP/Info/ccsip_iwf_init: Apr 21 14:50:57.213: //-1/000000000000/SIP/Info/ccsip_ipip_media_service_init: Apr 21 14:50:57.213: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry... Apr 21 14:50:57.213: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 54.171.127.192,Port 5060, Transport 1, SentBy Port 5060 Apr 21 14:50:57.213: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling reg_invoke_ip_first_hop() Apr 21 14:50:57.213: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling ip_best_local_address() Apr 21 14:50:57.213: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: return addr 62.133.18.252 Apr 21 14:50:57.213: //-1/613154AD8B3A/SIP/State/sipSPIChangeState: 0x49C73D28 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Apr 21 14:50:57.217: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 54.171.127.192,Port 5060, Transport 1, SentBy Port 5060 Apr 21 14:50:57.217: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 54.171.127.192,Port 5060, Transport 1, SentBy Port 5060 Apr 21 14:50:57.217: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling reg_invoke_ip_first_hop() Apr 21 14:50:57.217: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling ip_best_local_address() Apr 21 14:50:57.217: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: return addr 62.133.18.252 Apr 21 14:50:57.217: //-1/613154AD8B3A/SIP/Info/sipSPICheckAssertedIdConfig: Dialpeer match is not yet done Apr 21 14:50:57.217: //-1/613154AD8B3A/SIP/Info/sipSPIUpdateIdentity: SIP->PSTN: Setting Calling Number to +447552623221 Apr 21 14:50:57.217: //-1/613154AD8B3A/SIP/Info/sipSPICheckAssertedIdConfig: Dialpeer match is not yet done Apr 21 14:50:57.217: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentGTD: No GTD found in inbound container Apr 21 14:50:57.217: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentCSTA: No CSTA found in inbound container Apr 21 14:50:57.217: //-1/613154AD8B3A/SIP/Info/sipSPIUaddCcbToUASReqTable: ****Adding to UAS Request table. Apr 21 14:50:57.217: //-1/613154AD8B3A/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x49C73D28 key=02bea03153bed387ef71c1fec1707da3@0.0.0.0+442086295370 Apr 21 14:50:57.217: //-1/613154AD8B3A/SIP/Info/ccsipUpdateRedirectWithGtd: Redirecting Information: Number = +442086295370 Reason = 15 Counter = -1 Presentation Indicator = 0 Type of Number = 0 Numbering Plan Id = 0 Screening Indicator = 0 Apr 21 14:50:57.217: //-1/613154AD8B3A/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on carrier id Apr 21 14:50:57.217: //-1/613154AD8B3A/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on Incoming called number: +442086295370 Apr 21 14:50:57.217: //-1/613154AD8B3A/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on destination pattern: +447552623221 Apr 21 14:50:57.217: //-1/613154AD8B3A/SIP/Info/ccsipUpdateIncomingCallParams: ccCallInfo: Calling name , number +447552623221, Calling oct3 0x00, oct_3a 0x81, Called number +442086295370 Apr 21 14:50:57.217: //-1/613154AD8B3A/SIP/Info/sipSPIGetViaHostInURLFormat: VIA URL:sip:54.171.127.192:5060, Host:54.171.127.192 Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: : +447552623221 Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPIGetFromCalledPartyId: P-Called-Party-ID header not found Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPIGetPeerByCalledPartyId: P-Called-Party-ID not found or parse error Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPIGetCallConfig: No match found for P-Called-Party-ID Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/ccsip_validate_and_update_calling_info: PAI/PPI not configuredi for this dial-peer(200), use RPID/FROM header data Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPIUpdateCallingInfoUsingRpidOrFrom: Updating Calling Info with FROM header data Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPIGetCallConfig: Peer tag 200 matched for incoming call Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPICheckReliableProvStringtag: Unable to access supported header values Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header Apr 21 14:50:57.221: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling reg_invoke_ip_first_hop() Apr 21 14:50:57.221: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling ip_best_local_address() Apr 21 14:50:57.221: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: return addr 62.133.18.252 Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPICheckReliableProvStringtag: Unable to access supported header values Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPIGetCallConfig: Media Antitrombone disabled Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPISetMediaFlowMode: Storing the configured mode as FLOW-THROUGH Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPISetMediaFlowMode: xcoder high-density disabled Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPISetMediaFlowMode: Flow Mode set to FLOW_THROUGH Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPIGetCallConfig: Checking Video Type Rate=-1 video_codec_allowed=1F Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Media/sipSPICopyStunConfigFromPeerToCCB: Firewall traversal is not enabled Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPIGetModemInfoPerCall: peer_callID=0 Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPIGetCallConfig: Media forking disabled Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPISetOverlapConfiguration: Overlap signaling: FALSE: Endpt: SIP Trunk Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0 Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0 Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPIContinueNewMsgInvite: Calling name , number +447552623221, Calling oct3 0x00, oct_3a 0x80, ext_priv 0x00, Called number +442086295370, oct3 0x00 Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPIContinueNewMsgInvite: Carrier id code , prev_cid NONE, next_cid NONE, prev_tgrp NONE, next_tgrp NONE Apr 21 14:50:57.221: //-1/613154AD8B3A/SIP/Info/sipSPICheckReliableProvStringtag: Unable to access supported header values Apr 21 14:50:57.225: //-1/613154AD8B3A/SIP/Info/sipSPIValidateRequestUri: Not Enabled Apr 21 14:50:57.225: //-1/613154AD8B3A/SIP/Info/sipSPIRscmsmAvail: Value returned by check is = 0 Apr 21 14:50:57.225: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_IsSDPPassthruEnabled: - 0 Apr 21 14:50:57.225: //1096/613154AD8B3A/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_REQ Apr 21 14:50:57.225: //1096/613154AD8B3A/SIP/Event/Session-Timer/sipSTSLMain: dir:2, method:102, resp_code:0, container:47700BCC Apr 21 14:50:57.225: //1096/613154AD8B3A/SIP/Info/Session-Timer/sipSTSLExtractSessionExpiresHdr: Not received session expires header Apr 21 14:50:57.225: //1096/613154AD8B3A/SIP/Info/Session-Timer/sipSTSLGetInternalSREvent: E_STSL_INITIAL_SR_REQ Apr 21 14:50:57.225: //1096/613154AD8B3A/SIP/Event/Session-Timer/sipSTSLPrintTDContainer: Peer-Event: E_STSL_LEG_BY_LEG, SE Value:0, SE Refresher:none, Min-SE Value:1800, flags:2000 Apr 21 14:50:57.225: //1096/613154AD8B3A/SIP/Info/Session-Timer/sipSTSLMain: SE: 0;refresher:none peer refresher:none, flags:2000, posted event:E_STSL_INVALID_PEER_EVENT, reason:4 Configured SE:1800, Configured Min-SE:1800 Apr 21 14:50:57.225: //1096/613154AD8B3A/SIP/Info/sipSPIProcessHistoryInfoHeader: No HI headers recvd from app container Apr 21 14:50:57.225: //1096/613154AD8B3A/SIP/Info/sipSPIProcessReplacesHeader: No replaces hdr found Apr 21 14:50:57.225: //1096/613154AD8B3A/SIP/Info/sipSPIDoMediaNegotiation: Number of m-lines = 1 Apr 21 14:50:57.225: //1096/613154AD8B3A/SIP/Info/sipSPIValidateConnectionAddress: Dest port = 15600 SIP: (1096) Attribute mid, level 1 instance 1 not found. Apr 21 14:50:57.225: //1096/613154AD8B3A/SIP/Info/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Apr 21 14:50:57.225: //1096/613154AD8B3A/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 62.133.18.252 Apr 21 14:50:57.225: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) reserved for codec No Codec Apr 21 14:50:57.225: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 96 Apr 21 14:50:57.225: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) could not be reserved as its in use by other codec No Codec Apr 21 14:50:57.225: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPT: Requested payload-Type (101) is reserved by another application Apr 21 14:50:57.225: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 98 Apr 21 14:50:57.225: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 101 Apr 21 14:50:57.225: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAllocateFreeDynamicPT: Allocating free Dynamic Payload : 98 for Codec: Apr 21 14:50:57.225: //-1/xxxxxxxxxxxx/SIP/Info/rtpAvpCodec_to_voipCodec: Dynamic Payload :101 in SDP Body Apr 21 14:50:57.225: //1096/613154AD8B3A/SIP/Info/sipSPIDoAudioNegotiation: Codec (g711ulaw) Negotiation Successful on Static Payload for m-line 1 Apr 21 14:50:57.225: //1096/613154AD8B3A/SIP/Info/sipSPIDoPtimeNegotiation: One ptime attribute found - value:20 Apr 21 14:50:57.225: //-1/xxxxxxxxxxxx/SIP/Info/convert_ptime_to_codec_bytes: Values :Codec: g711ulaw ptime :20, codecbytes: 160 Apr 21 14:50:57.225: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20 Apr 21 14:50:57.225: //1096/613154AD8B3A/SIP/Media/sipSPIDoPtimeNegotiation: Offered ptime:20, Negotiated ptime:20 Negotiated codec bytes: 160 for codec g711ulaw Apr 21 14:50:57.225: //1096/613154AD8B3A/SIP/Info/sipSPISetFaxFlags: FAX_PASSTHROUGH = 0, END_FAX_PASSTHROUGH = 0 Apr 21 14:50:57.225: //1096/613154AD8B3A/SIP/Info/sipSPIDoDTMFRelayNegotiation: m-line index 1 Apr 21 14:50:57.225: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) reserved for codec Apr 21 14:50:57.225: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) reserved for codec Apr 21 14:50:57.225: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 98 Apr 21 14:50:57.225: //1096/613154AD8B3A/SIP/Info/sipSPIReserveRtpNtePayload: Reserved the payload type 101 for RTP-NTE Apr 21 14:50:57.225: //1096/613154AD8B3A/SIP/Info/sipSPIDoDTMFRelayNegotiation: RTP-NTE DTMF relay option Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sipSPIDoDTMFRelayNegotiation: Case of partial named event(NE) match in fmtp list of events. Apr 21 14:50:57.229: //-1/xxxxxxxxxxxx/SIP/Info/sip_sdp_get_modem_relay_cap_params: V150 NSE payload = 0, SSE payload = 0, SPRT payload=0 Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sip_select_modem_relay_params: X-tmr not present in SDP. Disable modem relay Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sipSPIGetSDPDirectionAttribute: No direction attribute present or multiple direction attributes that can't be handled for m-line:1 and num-a-lines:0 Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sipSPIDoAudioNegotiation: Codec negotiation successful for media line 1 payload_type=0, codec_bytes=160, codec=g711ulaw, dtmf_relay=rtp-nte stream_type=voice+dtmf (1), dest_ip_address=54.171.127.207, dest_port=15600 Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/State/sipSPIChangeStreamState: Stream (callid = -1) State changed from (STREAM_DEAD) to (STREAM_ADDING) Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Media/sipSPIUpdCallWithSdpInfo: Preferred Codec : g711ulaw, bytes :160 Preferred DTMF relay : rtp-nte Preferred NTE payload : 101 Early Media : No Delayed Media : No Bridge Done : No New Media : No DSP DNLD Reqd : No Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 62.133.18.252 Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/ccsip_offer_ans_handle_rcvd_sdp: Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/ccsip_offer_ans_process_event: Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/State/ccsip_cnfsm_debugs: OA:cur_container:ccsip_offer_ans_main_container, cur_state:S_SIP_EARLY_DIALOG_IDLE, event:E_SIP_INVITE_SDP_RCVD Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/ccsip_offer_ans_is_invite_offer_valid: - 1 Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/ccsip_offer_ans_common_offer_rcvd_hdlr: Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/ccsip_iwf_handle_network_event: Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/ccsip_iwf_process_event: Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_default_early_dialog_container, cur_state:S_SIP_IWF_SDP_IDLE, event:E_SIP_IWF_EV_RCVD_SDP Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sip_iwf_def_ed_rcvd_sdp_hdlr: Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: CallID 1096, sdp 0x49FD003C channels 0x49C7537C Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/copy_channels: callId 1096 size 0 ptr 0x47843CD0) Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: stream_callid = 1096, peer_stream_callid = -1 Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Hndl ptype 101 mline 1 Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_update_dynamic_codec_params: Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_upd_2833_dtmf_params: Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_upd_2833_dtmf_params: setting ipip_caps DTMF to RFC2833: callid = 1096, dtmf = 6 Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Hndl ptype 0 mline 1 Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Selecting codec g711ulaw Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/codec_found: Codec to be matched: 5 Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/codec_found: codecs[i] = 5 & codec = 5 are same.. Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: ADD AUDIO CODEC 5 Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_update_codec_params_in_channelInfo: Apr 21 14:50:57.229: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20 Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_update_codec_params_in_channelInfo: Adding negotiated codec 5 ptype 0 time 20, bytes 160 as channel 0 mline 1 ss 0 54.171.127.207:15600 Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Error/sipSPI_ipip_update_codec_params_in_channelInfo: failed to update call entry Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Media negotiation done: stream->negotiated_ptime=20,stream->negotiated_codec_bytes=160,stream->mline_index=1, media_ndx=1 Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Error/sipSPI_ipip_update_call_entry: failed to update call entry Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Copy sdp to channel- AFTER CODEC FILTERING: ccb->pld.ipip_caps.codecInfo[0].codec = 5 Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Copy sdp to channel- AFTER CODEC FILTERING: ccb->pld.ipip_caps.codecInfo[1].codec = -1 Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: srcChannelID = -1, dstChannelID = 1096 Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Media/sipSPIDisplayStreamInfo: Stream type : voice+dtmf Media line : 1 State : STREAM_ADDING (2) Stream address type : 1 Callid : 1096 Peer Callid : -1 RTP/SRTP Negotiated : 8 Negotiated Codec : g711ulaw, bytes :160 Nego. Codec payload : 0 (tx), 0 (rx) Negotiated DTMF relay : rtp-nte Negotiated NTE payload : 101 (tx), 101 (rx) Negotiated CN payload : 0 Media Srce Addr/Port : [62.133.18.252]:0 Media Dest Addr/Port : [54.171.127.207]:15600 Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_calculate_channel_count: Number of streams to report = 1 Apr 21 14:50:57.229: //-1/xxxxxxxxxxxx/SIP/Error/sipSPI_ipip_set_channel_count: Unable to set CHANNEL_COUNT for callid 1096 Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Error/sip_iwf_sip_copy_sdp_to_channelInfo: Channel count is not set at this point. Not SIP-SIP or SET_MODE is not done. Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:S_SIP_IWF_SDP_RCVD_AWAIT_PEER_EVENT Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/State/ccsip_cnfsm_debugs: OA:next_state:S_SIP_EARLY_DIALOG_OFFER_RCVD Apr 21 14:50:57.229: //1096/613154AD8B3A/SIP/Media/sipSPIUpdCallWithSdpInfo: Stream type : voice+dtmf Media line : 1 State : STREAM_ADDING (2) Stream address type : 1 Callid : 1096 Negotiated Codec : g711ulaw, bytes :160 Nego. Codec payload : 0 (tx), 0 (rx) Negotiated DTMF relay : rtp-nte Negotiated NTE payload : 101 (tx), 101 (rx) Negotiated CN payload : 0 Media Srce Addr/Port : [62.133.18.252]:0 Media Dest Addr/Port : [54.171.127.207]:15600 Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPIHandleInviteMedia: Negotiated Codec : g711ulaw, bytes :160 Preferred Codec : g711ulaw, bytes :160 Preferred DTMF relay 1 : 6 Preferred DTMF relay 2 : 9 Negotiated DTMF relay : 6 Preferred and Negotiated NTE payloads: 101 101 Preferred and Negotiated NSE payloads: 100 0 Preferred and Negotiated Modem Relay: 0 0 Preferred and Negotiated V150.1 Modem Passthrough: 0 0 Preferred and Negotiated V150.1 Modem Relay: 0 0 Preferred and Negotiated Modem Relay GwXid: 1 0 Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPIDoQoSNegotiationWithMediaLine: QOS negotiation for mline_index 1 Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPIDoStreamQoSNegotiation: Best effort Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPICanSetFallbackFlag: Local Fallback is not active Apr 21 14:50:57.233: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIReserveRtpPort: reserved port 18290 for stream 1 Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPIUpdateSrcSdpFixedPart: Reserving rtp port for stream 1, src_port=18290 Apr 21 14:50:57.233: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetMediaDirectionForStream: Setting Media direction SENDRECV for stream 1 Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPIUpdateSrcSdpVariablePart: Setting stream 1 portnum to 18290 Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPIUpdateSrcSdpVariablePart: SIP update src sdp, negoitated codec 5, payload type 0 Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPIUpdateSrcSdpVariablePart: Negotiated method of dtmf relayand pyld: 6 101 Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPIUpdateSrcSdpVariablePart: max_event 16 Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPIAddBillingInfoToCcb: sipCallId for billing records = 02bea03153bed387ef71c1fec1707da3@0.0.0.0 Apr 21 14:50:57.233: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentCPA: No CPA found in inbound container Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPIProcessCPA: No x-cisco-cpa content found Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0 Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_ExtractPassthruCopyListHdrsFromSipContainer: Unsupported header passthru is not configured and no headers are present in hdr_hash_queue Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_IsContentPassthruEnabled: - 0 Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_ExtractPassthruContentFromSipContainer: Passthru Content Not Enabled Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/ccsip_api_call_setup_ind: Unable to add unsupp headers to container Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/ccsip_api_call_setup_ind: Set Protocol information Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/ccsip_ipip_media_service_get_event_data: Event id = 24 Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_antiTrombone: Entered Antitrombone service Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_antiTrombone: Antitrombone service not configured Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_store_channel_info: Store channelInfo in CallInfo Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_store_channel_info: dtmf negotiation done, storing negotiated dtmf = 6, Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Media/sipSPIDisplayStreamInfo: Stream type : voice+dtmf Media line : 1 State : STREAM_ADDING (2) Stream address type : 1 Callid : 1096 Peer Callid : -1 RTP/SRTP Negotiated : 8 Negotiated Codec : g711ulaw, bytes :160 Nego. Codec payload : 0 (tx), 0 (rx) Negotiated DTMF relay : rtp-nte Negotiated NTE payload : 101 (tx), 101 (rx) Negotiated CN payload : 0 Media Srce Addr/Port : [62.133.18.252]:18290 Media Dest Addr/Port : [54.171.127.207]:15600 Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_calculate_channel_count: Number of streams to report = 1 Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_store_channel_info: Setting CHANNEL_COUNT = 1 for callid 1096 Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/sipSPIShrlCall: Check peer: 200 for Shared-Line call, callid: 1096 Apr 21 14:50:57.233: //1096/613154AD8B3A/SIP/Info/ccsip_set_bearer_capability: Bearer Capability: Speech (0x00) Apr 21 14:50:57.233: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQSIG: No QSIG Body found in inbound container Apr 21 14:50:57.233: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQ931: No RawMsg Body found in inbound container Apr 21 14:50:57.233: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICreateNewRawMsg: No Data to form The Raw Message Apr 21 14:50:57.237: //1096/613154AD8B3A/SIP/Info/sipSPIContinueNewMsgInvite: ccsip_api_call_setup_ind returned: SIP_SUCCESS Apr 21 14:50:57.237: //1096/613154AD8B3A/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 448 to table Apr 21 14:50:57.237: //1096/613154AD8B3A/SIP/Info/sipSPIUpdateCallEntry: Call 1096 set InfoType to SPEECH Apr 21 14:50:57.237: //1096/613154AD8B3A/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_RESP Apr 21 14:50:57.237: //1096/613154AD8B3A/SIP/Event/Session-Timer/sipSTSLMain: dir:1, method:102, resp_code:100, container:476FD894 Apr 21 14:50:57.237: //1096/613154AD8B3A/SIP/Info/Session-Timer/sipSTSLValidateSessRefreshMsg: Ignoring 1xx response for session timer processing Apr 21 14:50:57.237: //1096/613154AD8B3A/SIP/Info/addAllowHeaderKpml: KPML Subscriptions allowed. Apr 21 14:50:57.237: //1096/613154AD8B3A/SIP/Info/sipSPISendInviteResponse: Associated container=0x476FD894 to Invite Response 100 Apr 21 14:50:57.237: //1096/613154AD8B3A/SIP/Transport/sipSPITransportSendMessage: msg=0x49FE1574, addr=54.171.127.192, port=5060, sentBy_port=5060, local_addr=, is_req=0, transport=1, switch=0, callBack=0x0 Apr 21 14:50:57.237: //1096/613154AD8B3A/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 21 14:50:57.237: //1096/613154AD8B3A/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Apr 21 14:50:57.237: //1096/613154AD8B3A/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x49FE1574 to default port=5060 Apr 21 14:50:57.237: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetAgeingTimer: Aging timer initiated for holder=0x49FD89F0,addr=54.171.127.192 Apr 21 14:50:57.237: //-1/xxxxxxxxxxxx/SIP/Transport/sipCreateConnHolder: Created new holder=0x49FD89F0, addr=54.171.127.192; nailed=FALSE Apr 21 14:50:57.237: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostRequestConnection: Posting UDP conn create request for addr=54.171.127.192, port=5060, context=0x4847BB1C Apr 21 14:50:57.237: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetConnWaitTimer: Wait timer set for connection=0x4847BFE4,addr=54.171.127.192, port=5060 Apr 21 14:50:57.237: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetConnWaitTimer: Wait Conn Timer started for 5000 msec Apr 21 14:50:57.237: //-1/xxxxxxxxxxxx/SIP/Transport/sipCreateConnInstance: Created new initiated conn=0x4847BFE4, connid=-1, addr=54.171.127.192, port=5060, local_addr=, transport=UDP Apr 21 14:50:57.237: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:54.171.127.192, rport:5060 with laddr: Apr 21 14:50:57.237: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x49C73D28 with connection=0x4847BFE4 Apr 21 14:50:57.237: //1096/613154AD8B3A/SIP/Transport/sipTransportLogicSendMsg: Waiting for Connection for sending msg=0x49FE1574 Apr 21 14:50:57.237: //1096/613154AD8B3A/SIP/Transport/sipSPITransportSendMessage: Deferred sending msg=0x49FE1574 Apr 21 14:50:57.237: //1096/613154AD8B3A/SIP/State/sipSPIChangeState: 0x49C73D28 : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_RECD_INVITE, SUBSTATE_NONE) Apr 21 14:50:57.237: //1096/613154AD8B3A/SIP/Info/sipSPIProcessContactInfo: Previous Hop 54.171.127.192:5060 Apr 21 14:50:57.245: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_PROCEEDING Apr 21 14:50:57.245: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x49CA0CA8) with key=[1467] to table Apr 21 14:50:57.245: //-1/000000000000/SIP/Info/ccsip_offer_ans_init: Apr 21 14:50:57.245: //-1/000000000000/SIP/Info/ccsip_iwf_init: Apr 21 14:50:57.245: //-1/000000000000/SIP/Info/ccsip_ipip_media_service_init: Apr 21 14:50:57.245: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry... Apr 21 14:50:57.245: //1097/000000000000/SIP/State/sipSPIChangeState: 0x49CA0CA8 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Apr 21 14:50:57.245: //1097/000000000000/SIP/Info/ccsip_call_setup_request: Set Protocol information Apr 21 14:50:57.245: //1097/000000000000/SIP/Info/ccsip_iwf_handle_peer_event: Apr 21 14:50:57.245: //1097/000000000000/SIP/Info/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 1, Event Id: 174 Apr 21 14:50:57.245: //1097/000000000000/SIP/Info/ccsip_iwf_process_event: Apr 21 14:50:57.245: //1097/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_default_early_dialog_container, cur_state:S_SIP_IWF_SDP_IDLE, event:E_SIP_IWF_EV_SET_MODE Apr 21 14:50:57.245: //1097/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container 1 INVITE Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER Allow-Events: kpml, telephone-event Remote-Party-ID: "Theofilos Tzachristas" ;party=called;screen=yes;privacy=off Contact: Record-Route: Server: Cisco-SIPGateway/IOS-12.x Content-Length: 0 Apr 21 14:50:59.169: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.111.1]:5060, local_address:[ - ] Apr 21 14:50:59.169: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Apr 21 14:50:59.169: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Apr 21 14:50:59.169: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 503 Service Unavailable Via: SIP/2.0/UDP 192.168.110.231:5060;branch=z9hG4bK2FD26E6 From: ;tag=2FBB4C80-25FE To: ;tag=380975~6a31a7a9-e005-4f2b-bcd0-b49c1655cf54-24255743 Date: Fri, 21 Apr 2017 13:50:57 GMT Call-ID: 6138A7BE-25D011E7-8B40A40C-C2172E6F@192.168.110.231 CSeq: 101 INVITE Allow-Events: presence Reason: Q.850;cause=47 Content-Length: 0 Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Info/sipSPICheckResponseExt: INVITE response with no RSEQ - disable IS_REL1XX Apr 21 14:50:59.173: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentGTD: No GTD found in inbound container Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Info/sipSPIPresendProcessing: Presend Processing called for 1 event Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Info/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Info/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Info/ccsip_offer_ans_handle_call_active: Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Info/ccsip_offer_ans_process_event: Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/State/ccsip_cnfsm_debugs: OA:cur_container:ccsip_offer_ans_main_container, cur_state:S_SIP_EARLY_DIALOG_OFFER_SENT, event:E_SIP_DIALOG_ESTD Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Info/ccsip_offer_ans_process_event: O/A - cnfsm ret 2 Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Info/sipSPISendAck: Associated container=0x476FE5A4 to Ack Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Transport/sipSPISendAck: Sending ACK to the transport layer Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Dial peer configuration, Switch Transport is FALSE Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Transport/sipSPITransportSendMessage: msg=0x4ACCAAD8, addr=192.168.111.1, port=5060, sentBy_port=0, local_addr=, is_req=1, transport=1, switch=0, callBack=0x0 Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Apr 21 14:50:59.173: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:192.168.111.1, rport:5060 with laddr: Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x4ACCAAD8 Apr 21 14:50:59.173: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x4ACCAAD8, addr=192.168.111.1, port=5060, local_addr=, connId=3 for UDP Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Info/act_recdproc_new_message_response: Received a 4/5/6xx message with StatusCode: 503 Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Info/ccsip_set_release_source_for_peer: ownCallId[1097], src[4] Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Info/sipSPIInitiateDisconnect: Initiate call disconnect(63) for outgoing call Apr 21 14:50:59.173: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQSIG: No QSIG Body found in inbound container Apr 21 14:50:59.173: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQ931: No RawMsg Body found in inbound container Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Info/ccsip_ipip_media_service_get_event_data: Event id = 26 Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Info/sipSPI_ipip_antiTrombone: Entered Antitrombone service Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Info/sipSPI_ipip_antiTrombone: Antitrombone service not configured Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Info/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0 Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Info/sipSPI_ipip_ExtractPassthruCopyListHdrsFromSipContainer: Unsupported header passthru is not configured and no headers are present in hdr_hash_queue Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Info/sipSPI_ipip_IsContentPassthruEnabled: - 0 Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Info/sipSPI_ipip_ExtractPassthruContentFromSipContainer: Passthru Content Not Enabled Apr 21 14:50:59.173: //1097/613154AD8B3A/SIP/Info/sipAddSipContainerToCallEntry: Unable to add passthru hdrs to container Apr 21 14:50:59.177: //1097/613154AD8B3A/SIP/State/sipSPIChangeState: 0x49CA0CA8 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING) to (STATE_DISCONNECTING, SUBSTATE_NONE) Apr 21 14:50:59.177: //1097/613154AD8B3A/SIP/Info/ccsip_call_statistics: Requesting stats for callid=1097 Apr 21 14:50:59.177: //1097/613154AD8B3A/SIP/Info/ccsip_call_statistics: Stats request failed for callid=1097, dstCallID=-1, rc=-7 Apr 21 14:50:59.177: //1097/613154AD8B3A/SIP/Info/ccsip_ipip_media_service_get_event_data: Event id = 26 Apr 21 14:50:59.177: //1097/613154AD8B3A/SIP/Info/sipSPI_ipip_antiTrombone: Entered Antitrombone service Apr 21 14:50:59.177: //1097/613154AD8B3A/SIP/Info/sipSPI_ipip_antiTrombone: Antitrombone service not configured Apr 21 14:50:59.177: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT Apr 21 14:50:59.177: //1096/613154AD8B3A/SIP/Info/ccsip_query_codec_info: Negotiated codec = 5 Apr 21 14:50:59.177: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_codec_byte_transrating: tranrating not enabled on peers, return FALSE Apr 21 14:50:59.177: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 8 Apr 21 14:50:59.177: //1097/613154AD8B3A/SIP/Info/sipSPIIcpifUpdate: CallState: 2 Playout: 0 DiscTime:80080588 ConnTime 0 Apr 21 14:50:59.177: //1097/613154AD8B3A/SIP/Media/sipSPIDestroyRtpSession: stream:49FF2988 Apr 21 14:50:59.177: //1097/613154AD8B3A/SIP/State/sipSPIChangeState: 0x49CA0CA8 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE) Apr 21 14:50:59.177: //1097/613154AD8B3A/SIP/Call/sipSPICallInfo: The Call Setup Information is: Call Control Block (CCB) : 0x49CA0CA8 State of The Call : STATE_DEAD TCP Sockets Used : NO Calling Number : 907552623221 Called Number : 442086295370 Source IP Address (Sig ): 192.168.110.231 Destn SIP Req Addr:Port : 192.168.111.1:5060 Destn SIP Resp Addr:Port : 192.168.111.1:5060 Destination Name : 192.168.111.1 Apr 21 14:50:59.177: //1097/613154AD8B3A/SIP/Call/sipSPIMediaCallInfo: Number of Media Streams: 1 Media Stream : 1 Negotiated Codec : No Codec Negotiated Codec Bytes : 0 Nego. Codec payload : 255 (tx), 255 (rx) Negotiated Dtmf-relay : 0 Dtmf-relay Payload : 0 (tx), 0 (rx) Source IP Address (Media): 192.168.110.231 Source IP Port (Media): 17496 Destn IP Address (Media): - Destn IP Port (Media): 0 Orig Destn IP Address:Port (Media): [ - ]:0 Apr 21 14:50:59.177: //1097/613154AD8B3A/SIP/Call/sipSPICallInfo: Disconnect Cause (CC) : 63 Disconnect Cause (SIP) : 503 Apr 21 14:50:59.177: //1097/613154AD8B3A/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 449 Apr 21 14:50:59.181: //1096/613154AD8B3A/SIP/Info/ccsip_call_statistics: Stats are not supported for IPIP call. Apr 21 14:50:59.181: //1096/613154AD8B3A/SIP/Info/ccsip_ipip_media_service_get_event_data: Event id = 26 Apr 21 14:50:59.181: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_antiTrombone: Entered Antitrombone service Apr 21 14:50:59.181: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_antiTrombone: Antitrombone service not configured Apr 21 14:50:59.181: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT Apr 21 14:50:59.181: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 8 Apr 21 14:50:59.181: //1096/613154AD8B3A/SIP/Error/act_sentalert_disconnect: Disconnect cause from ccapi :63 and sip_disc_cause: 500 Apr 21 14:50:59.181: //1096/613154AD8B3A/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_RESP Apr 21 14:50:59.181: //1096/613154AD8B3A/SIP/Event/Session-Timer/sipSTSLMain: dir:1, method:102, resp_code:500, container:476FD1B4 Apr 21 14:50:59.181: //1096/613154AD8B3A/SIP/Info/Session-Timer/sipSTSLGetInternalSREvent: E_STSL_INITIAL_SR_RESP Apr 21 14:50:59.181: //1096/613154AD8B3A/SIP/Info/Session-Timer/sipSTSLMain: SE: 0;refresher:none peer refresher:none, flags:80, posted event:E_STSL_INVALID_PEER_EVENT, reason:3 Configured SE:1800, Configured Min-SE:1800 Apr 21 14:50:59.181: //1096/613154AD8B3A/SIP/Info/sipSPIPresendProcessing: Presend Processing called for 3 event Apr 21 14:50:59.181: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Apr 21 14:50:59.181: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Apr 21 14:50:59.181: //1096/613154AD8B3A/SIP/Info/sipSPISendInviteResponse: Associated container=0x476FD1B4 to Invite Response 500 Apr 21 14:50:59.185: //1096/613154AD8B3A/SIP/Transport/sipSPITransportSendMessage: msg=0x4ACCA8E8, addr=54.171.127.192, port=5060, sentBy_port=5060, local_addr=, is_req=0, transport=1, switch=0, callBack=0x41AD5860 Apr 21 14:50:59.185: //1096/613154AD8B3A/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 21 14:50:59.185: //1096/613154AD8B3A/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Apr 21 14:50:59.185: //1096/613154AD8B3A/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x4ACCA8E8 to default port=5060 Apr 21 14:50:59.185: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:54.171.127.192, rport:5060 with laddr: Apr 21 14:50:59.185: //1096/613154AD8B3A/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x4ACCA8E8 Apr 21 14:50:59.185: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x4ACCA8E8, addr=54.171.127.192, port=5060, local_addr=, connId=4 for UDP Apr 21 14:50:59.185: //1096/613154AD8B3A/SIP/Info/sentErrResDisconnecting: Sent an 3456XX Error Response Apr 21 14:50:59.185: //1096/613154AD8B3A/SIP/State/sipSPIChangeState: 0x49C73D28 : State change from (STATE_SENT_ALERTING, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE) Apr 21 14:50:59.185: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: ACK sip:442086295370@192.168.111.1:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.110.231:5060;branch=z9hG4bK2FD26E6 From: ;tag=2FBB4C80-25FE To: ;tag=380975~6a31a7a9-e005-4f2b-bcd0-b49c1655cf54-24255743 Date: Fri, 21 Apr 2017 13:50:57 GMT Call-ID: 6138A7BE-25D011E7-8B40A40C-C2172E6F@192.168.110.231 Max-Forwards: 70 CSeq: 101 ACK Allow-Events: kpml, telephone-event Content-Length: 0 Apr 21 14:50:59.185: //1096/613154AD8B3A/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 500 Internal Server Error Via: SIP/2.0/UDP 54.171.127.192:5060;branch=z9hG4bKa4b8.68b062a2.0,SIP/2.0/UDP 172.18.204.154:5060;rport=5060;received=172.18.204.154;branch=z9hG4bK32c36cbd-f873-43ec-b213-73a360cab2ad_6772d868_230-11839665410571672965 From: ;tag=58203968_6772d868_32c36cbd-f873-43ec-b213-73a360cab2ad To: ;tag=2FBB4C9C-137C Date: Fri, 21 Apr 2017 13:50:57 GMT Call-ID: 02bea03153bed387ef71c1fec1707da3@0.0.0.0 CSeq: 1 INVITE Allow-Events: kpml, telephone-event Server: Cisco-SIPGateway/IOS-12.x Reason: Q.850;cause=63 Content-Length: 0 Apr 21 14:50:59.201: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [54.171.127.192]:5060, local_address:[ - ] Apr 21 14:50:59.205: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Apr 21 14:50:59.205: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Apr 21 14:50:59.205: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: ACK sip:+442086295370@62.133.18.252 SIP/2.0 Via: SIP/2.0/UDP 54.171.127.192:5060;branch=z9hG4bKa4b8.68b062a2.0 From: ;tag=58203968_6772d868_32c36cbd-f873-43ec-b213-73a360cab2ad Call-ID: 02bea03153bed387ef71c1fec1707da3@0.0.0.0 To: ;tag=2FBB4C9C-137C CSeq: 1 ACK Max-Forwards: 70 User-Agent: Twilio Gateway Content-Length: 0 Apr 21 14:50:59.205: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog Apr 21 14:50:59.205: //1096/613154AD8B3A/SIP/Info/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x49C73D28 Apr 21 14:50:59.205: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 54.171.127.192,Port 5060, Transport 1, SentBy Port 5060 Apr 21 14:50:59.205: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 54.171.127.192,Port 5060, Transport 1, SentBy Port 5060 Apr 21 14:50:59.205: //1096/613154AD8B3A/SIP/Info/sipSPIIcpifUpdate: CallState: 2 Playout: 0 DiscTime:80080590 ConnTime 0 Apr 21 14:50:59.205: //1096/613154AD8B3A/SIP/State/sipSPIChangeState: 0x49C73D28 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE) Apr 21 14:50:59.205: //1096/613154AD8B3A/SIP/Call/sipSPICallInfo: The Call Setup Information is: Call Control Block (CCB) : 0x49C73D28 State of The Call : STATE_DEAD TCP Sockets Used : NO Calling Number : +447552623221 Called Number : +442086295370 Source IP Address (Sig ): 62.133.18.252 Destn SIP Req Addr:Port : 54.171.127.192:5060 Destn SIP Resp Addr:Port : 54.171.127.192:5060 Destination Name : 54.171.127.192 Apr 21 14:50:59.205: //1096/613154AD8B3A/SIP/Call/sipSPIMediaCallInfo: Number of Media Streams: 1 Media Stream : 1 Negotiated Codec : g711ulaw Negotiated Codec Bytes : 160 Nego. Codec payload : 0 (tx), 0 (rx) Negotiated Dtmf-relay : 6 Dtmf-relay Payload : 101 (tx), 101 (rx) Source IP Address (Media): 62.133.18.252 Source IP Port (Media): 18290 Destn IP Address (Media): 54.171.127.207 Destn IP Port (Media): 15600 Orig Destn IP Address:Port (Media): [ - ]:0 Apr 21 14:50:59.205: //1096/613154AD8B3A/SIP/Call/sipSPICallInfo: Disconnect Cause (CC) : 63 Disconnect Cause (SIP) : 500 Apr 21 14:50:59.205: //1096/613154AD8B3A/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 448 Apr 21 14:50:59.205: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[1466] removed. Apr 21 14:50:59.209: //1096/613154AD8B3A/SIP/Info/sipSPIUdeleteCcbFromUASReqTable: ****Deleting from UAS Request table. Apr 21 14:50:59.209: //1096/613154AD8B3A/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x49C73D28 key=02bea03153bed387ef71c1fec1707da3@0.0.0.0+442086295370 Apr 21 14:50:59.209: //1096/613154AD8B3A/SIP/Info/sipSPIUdeleteCcbFromUASRespTable: ****Deleting from UAS Response table. Apr 21 14:50:59.209: //1096/613154AD8B3A/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x49C73D28 key=02bea03153bed387ef71c1fec1707da3@0.0.0.02FBB4C9C-137C Apr 21 14:50:59.209: //1096/613154AD8B3A/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Apr 21 14:50:59.209: //1096/613154AD8B3A/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Apr 21 14:50:59.209: //1096/613154AD8B3A/SIP/Info/ccsip_offer_ans_delete: Apr 21 14:50:59.209: //1096/613154AD8B3A/SIP/Info/ccsip_iwf_delete: Apr 21 14:50:59.209: //1096/613154AD8B3A/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 49C73D28 Apr 21 14:50:59.209: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[1466]