!!!!!!!!!!!! ! WORKING debug, but without using the registar in the Sip trunk. Just to spot any differences from the non-working debug. !!!!!!!!!!!! CMELDA001# Aug 12 12:49:10.258: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [10.30.0.2]:5060, local_address:[10.244.3.1] Aug 12 12:49:10.258: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Aug 12 12:49:10.258: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Aug 12 12:49:10.258: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: INVITE sip:103@10.244.3.1;user=phone;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.30.0.2:5060;branch=z9hG4bK-d8754z-89dfab4048c4270b-1---d8754z-;rport Max-Forwards: 70 Contact: To: From: "TESTE ANGOLA";tag=5982796e Call-ID: MmJjMmNkNjAyOGY5YjkzYjM5ZDYzN2E3YWQ1Njk2YmY. CSeq: 1 INVITE Session-Expires: 1800 Min-SE: 90 Allow: INVITE, OPTIONS, BYE, ACK, CANCEL, INFO, REGISTER, REFER, PRACK, SUBSCRIBE, NOTIFY, MESSAGE, UPDATE Content-Type: application/sdp Supported: timer, 100rel User-Agent: Aastra MX-ONE SN/13.211.3 Privacy: none Content-Length: 575 v=0 o=0040010001 6046661521466465382 6046661521466699375 IN IP4 10.30.0.7 s=MX-ONE c=IN IP4 10.30.0.7 t=0 0 m=audio 39554 RTP/AVP 8 0 18 4 101 13 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=rtpmap:4 G723/8000 a=rtpmap:101 telephone-event/8000 a=rtpmap:13 CN/8000 a=ptime:30 a=sqn:0 a=cdsc:1 image udptl t38 a=cpar:a=T38FaxVersion:0 a=cpar:a=T38MaxBitRate:14400 a=cpar:a=T38FaxRateManagement:transferredTCF a=cpar:a=T38FaxMaxBuffer:9772 a=cpar:a=T38FaxMaxDatagram:1472 a=cpar:a=T38FaxUdpEC:t38UDPRedundancy a=silenceSupp:on - - - - Aug 12 12:49:10.258: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog Aug 12 12:49:10.258: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x889B72B8) with key=[9] to table Aug 12 12:49:10.258: //-1/000000000000/SIP/Info/ccsip_offer_ans_init: Aug 12 12:49:10.258: //-1/000000000000/SIP/Info/ccsip_iwf_init: Aug 12 12:49:10.258: //-1/000000000000/SIP/Info/ccsip_ipip_media_service_init: Aug 12 12:49:10.258: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry... Aug 12 12:49:10.258: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.30.0.2,Port 5060, Transport 1, SentBy Port 5060 Aug 12 12:49:10.258: //-1/000000000000/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 10.244.3.1 Aug 12 12:49:10.258: //-1/E39C859F800E/SIP/State/sipSPIChangeState: 0x889B72B8 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Aug 12 12:49:10.258: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.30.0.2,Port 5060, Transport 1, SentBy Port 5060 Aug 12 12:49:10.258: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone WAT to SIP default timezone = GMT Aug 12 12:49:10.258: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.30.0.2,Port 5060, Transport 1, SentBy Port 5060 Aug 12 12:49:10.258: //-1/E39C859F800E/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 10.244.3.1 Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPICheckAssertedIdConfig: Dialpeer match is not yet done Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPICheckAssertedIdConfig: Dialpeer match is not yet done Aug 12 12:49:10.262: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetPrivacy: No valid Privacy found Aug 12 12:49:10.262: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentGTD: No GTD found in inbound container Aug 12 12:49:10.262: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentCSTA: No CSTA found in inbound container Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPIUaddCcbToUASReqTable: ****Adding to UAS Request table. Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x889B72B8 key=MmJjMmNkNjAyOGY5YjkzYjM5ZDYzN2E3YWQ1Njk2YmY.103 Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on carrier id Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on Incoming called number: 103 Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on destination pattern: 726 Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/ccsipUpdateIncomingCallParams: ccCallInfo: Calling name TESTE ANGOLA, number 726, Calling oct3 0x00, oct_3a 0x80, Called number 103 Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPIGetViaHostInURLFormat: VIA URL:sip:10.30.0.2:5060, Host:10.30.0.2 Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: : 726 Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPIGetFromCalledPartyId: P-Called-Party-ID header not found Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPIGetPeerByCalledPartyId: P-Called-Party-ID not found or parse error Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPIGetCallConfig: No match found for P-Called-Party-ID Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPIGetCallConfig: Peer tag 1 matched for incoming call Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 10.244.3.1 Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPIGetCallConfig: Media Antitrombone disabled Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPISetMediaFlowMode: Storing the configured mode as FLOW-THROUGH Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPISetMediaFlowMode: xcoder high-density disabled Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPISetMediaFlowMode: Flow Mode set to FLOW_THROUGH Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPIGetCallConfig: Using Voice Class Codec, tag = 1 and offer-all is = FALSE Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Media/sipSPICopyStunConfigFromPeerToCCB: Firewall traversal is not enabled Aug 12 12:49:10.262: //-1/E39C859F800E/SIP/Info/sipSPIGetModemInfoPerCall: peer_callID=0 Aug 12 12:49:10.266: //-1/E39C859F800E/SIP/Info/sipSPIGetCallConfig: Media forking disabled Aug 12 12:49:10.266: //-1/E39C859F800E/SIP/Info/sipSPISetOverlapConfiguration: Overlap signaling: FALSE: Endpt: SIP Trunk Aug 12 12:49:10.266: //-1/E39C859F800E/SIP/Info/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0 Aug 12 12:49:10.266: //-1/E39C859F800E/SIP/Info/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0 Aug 12 12:49:10.266: //-1/E39C859F800E/SIP/Info/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled Aug 12 12:49:10.266: //-1/E39C859F800E/SIP/Info/sipSPIContinueNewMsgInvite: Calling name TESTE ANGOLA, number 726, Calling oct3 0x00, oct_3a 0x80, ext_priv 0x00, Called number 103, oct3 0x00 Aug 12 12:49:10.266: //-1/E39C859F800E/SIP/Info/sipSPIContinueNewMsgInvite: Carrier id code , prev_cid NONE, next_cid NONE, prev_tgrp NONE, next_tgrp NONE Aug 12 12:49:10.266: //-1/E39C859F800E/SIP/Info/sipSPIContinueNewMsgInvite: Requires reliable-provisional support Aug 12 12:49:10.266: //-1/E39C859F800E/SIP/Info/sipSPIValidateRequestUri: Not Enabled Aug 12 12:49:10.266: //-1/E39C859F800E/SIP/Info/sipSPIRscmsmAvail: Value returned by check is = 0 Aug 12 12:49:10.266: //5/E39C859F800E/SIP/Info/sipSPI_ipip_IsSDPPassthruEnabled: - 0 Aug 12 12:49:10.266: //5/E39C859F800E/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_REQ Aug 12 12:49:10.266: //5/E39C859F800E/SIP/Event/Session-Timer/sipSTSLMain: dir:2, method:102, resp_code:0, container:88C357A4 Aug 12 12:49:10.266: //5/E39C859F800E/SIP/Info/Session-Timer/sipSTSLExtractSessionExpiresHdr: Session-Expires value: 1800 refresher: none Aug 12 12:49:10.266: //5/E39C859F800E/SIP/Info/Session-Timer/sipSTSLExtractMinSEHdr: Min-SE Duration: 90 Aug 12 12:49:10.266: //5/E39C859F800E/SIP/Info/Session-Timer/sipSTSLGetInternalSREvent: E_STSL_INITIAL_SR_REQ Aug 12 12:49:10.266: //5/E39C859F800E/SIP/Info/Session-Timer/sipSTSLInitialSRReqPeerEventGen: sending received session expires to the peer leg Aug 12 12:49:10.266: //5/E39C859F800E/SIP/Event/Session-Timer/sipSTSLPrintTDContainer: Peer-Event: E_STSL_PASS_ST_PARAMS, SE Value:1800, SE Refresher:none, Min-SE Value:1800, flags:2001 Aug 12 12:49:10.266: //5/E39C859F800E/SIP/Info/Session-Timer/sipSTSLMain: SE: 1800;refresher:none peer refresher:none, flags:2001, posted event:E_STSL_INVALID_PEER_EVENT, reason:4 Configured SE:1800, Configured Min-SE:1800 Aug 12 12:49:10.266: //5/E39C859F800E/SIP/Info/sipSPIProcessHistoryInfoHeader: No HI headers recvd from app container Aug 12 12:49:10.266: //5/E39C859F800E/SIP/Info/sipSPIProcessDiversionHeader: No diversion headers recvd from app container Aug 12 12:49:10.266: //5/E39C859F800E/SIP/Info/sipSPIProcessReplacesHeader: No replaces hdr found Aug 12 12:49:10.266: //5/E39C859F800E/SIP/Info/sipSPIDoMediaNegotiation: Number of m-lines = 1 Aug 12 12:49:10.266: //5/E39C859F800E/SIP/Info/sipSPIValidateConnectionAddress: Dest port = 39554 SIP: (5) Attribute mid, level 1 instance 1 not found. Aug 12 12:49:10.266: //5/E39C859F800E/SIP/Info/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Aug 12 12:49:10.266: //5/E39C859F800E/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.244.3.1 Aug 12 12:49:10.266: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) reserved for codec No Codec Aug 12 12:49:10.266: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 96 Aug 12 12:49:10.266: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) could not be reserved as its in use by other codec No Codec Aug 12 12:49:10.266: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPT: Requested payload-Type (101) is reserved by another application Aug 12 12:49:10.266: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 98 Aug 12 12:49:10.266: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 101 Aug 12 12:49:10.266: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAllocateFreeDynamicPT: Allocating free Dynamic Payload : 98 for Codec: Aug 12 12:49:10.266: //5/E39C859F800E/SIP/Info/sipSPIDoAudioNegotiation: Codec (g711ulaw) Negotiation Successful on Static Payload for m-line 1 Aug 12 12:49:10.266: //5/E39C859F800E/SIP/Info/sipSPIDoPtimeNegotiation: One ptime attribute found - value:30 Aug 12 12:49:10.266: //-1/xxxxxxxxxxxx/SIP/Info/convert_ptime_to_codec_bytes: Values :Codec: g711ulaw ptime :30, codecbytes: 240 Aug 12 12:49:10.266: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Media/sipSPIDoPtimeNegotiation: Offered ptime:30, Negotiated ptime:20 Negotiated codec bytes: 160 for codec g711ulaw Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sipSPISetFaxFlags: FAX_PASSTHROUGH = 0, END_FAX_PASSTHROUGH = 0 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sipSPIDoDTMFRelayNegotiation: m-line index 1 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sipSPIDoDTMFRelayNegotiation: Requested DTMF-RELAY option(s) not found in Preferred DTMF-RELAY option list! Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sipSPIStreamTypeAndDtmfRelay: DTMF Relay mode: Inband Voice Aug 12 12:49:10.270: //-1/xxxxxxxxxxxx/SIP/Info/sip_sdp_get_modem_relay_cap_params: V150 NSE payload = 0, SSE payload = 0, SPRT payload=0 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sip_select_modem_relay_params: X-tmr not present in SDP. Disable modem relay Aug 12 12:49:10.270: //5/E39C859F800E/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 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sipSPIDoAudioNegotiation: Codec negotiation successful for media line 1 payload_type=0, codec_bytes=160, codec=g711ulaw, dtmf_relay=inband-voice stream_type=voice-only (0), dest_ip_address=10.30.0.7, dest_port=39554 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/State/sipSPIChangeStreamState: Stream (callid = -1) State changed from (STREAM_DEAD) to (STREAM_ADDING) Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Media/sipSPIUpdCallWithSdpInfo: Preferred Codec : g711ulaw, bytes :160 Preferred DTMF relay : inband-voice Preferred NTE payload : 98 Early Media : No Delayed Media : No Bridge Done : No New Media : No DSP DNLD Reqd : No Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.244.3.1 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/ccsip_offer_ans_handle_rcvd_sdp: Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/ccsip_offer_ans_process_event: Aug 12 12:49:10.270: //5/E39C859F800E/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 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/ccsip_offer_ans_is_invite_offer_valid: - 1 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/ccsip_offer_ans_common_offer_rcvd_hdlr: Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/ccsip_iwf_handle_network_event: Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/ccsip_iwf_process_event: Aug 12 12:49:10.270: //5/E39C859F800E/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 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sip_iwf_def_ed_rcvd_sdp_hdlr: Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: CallID 5, sdp 0x882F6754 channels 0x889B890C Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/copy_channels: callId 5 size 0 ptr 0x8A0531B4) Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: stream_callid = 5, peer_stream_callid = -1 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Hndl ptype 8 mline 1 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Selecting codec g711alaw Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/codec_found: Codec to be matched: 6 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/codec_found: No match for the codecs found.. Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Hndl ptype 0 mline 1 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Selecting codec g711ulaw Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/codec_found: Codec to be matched: 5 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/codec_found: codecs[i] = 5 & codec = 5 are same.. Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: ADD AUDIO CODEC 5 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sipSPI_ipip_update_codec_params_in_channelInfo: Aug 12 12:49:10.270: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20 Aug 12 12:49:10.270: //5/E39C859F800E/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 1 10.30.0.7:39554 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Error/sipSPI_ipip_update_codec_params_in_channelInfo: failed to update call entry Aug 12 12:49:10.270: //5/E39C859F800E/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 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Hndl ptype 18 mline 1 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Media/sipSPISelectCodecVersion: Codec (g729br8) is not in preferred list Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sipSPI_ipip_update_static_codec_params: An exact codec match not configured, using interoperable codec g729r8 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Selecting codec g729r8 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/codec_found: Codec to be matched: 16 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/codec_found: codecs[i] = 16 & codec = 16 are same.. Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: ADD AUDIO CODEC 16 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sipSPI_ipip_update_codec_params_in_channelInfo: Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sipSPI_ipip_GetCodecBytePtimeFromSdp: Aug 12 12:49:10.270: //-1/xxxxxxxxxxxx/SIP/Info/convert_ptime_to_codec_bytes: Values :Codec: g729r8 ptime :30, codecbytes: 30 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sipSPI_ipip_update_codec_params_in_channelInfo: Adding negotiated codec 16 ptype 18 time 30, bytes 20 as channel 1 mline 1 ss 1 10.30.0.7:39554 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Error/sipSPI_ipip_update_codec_params_in_channelInfo: failed to update call entry Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Hndl ptype 4 mline 1 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Media/sipSPISelectCodecVersion: Codec (No Codec ) is not in preferred list Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sipSPI_ipip_update_static_codec_params: An exact codec match not configured, using interoperable codec g729r8 pre-ietf Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Selecting codec g729r8 pre-ietf Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/codec_found: Codec to be matched: 0 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/codec_found: codecs[i] = 16 & codec = 0 are same.. Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: ADD AUDIO CODEC 0 Aug 12 12:49:10.270: //5/E39C859F800E/SIP/Info/sipSPI_ipip_update_codec_params_in_channelInfo: Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sipSPI_ipip_GetCodecBytePtimeFromSdp: Aug 12 12:49:10.274: //-1/xxxxxxxxxxxx/SIP/Info/convert_ptime_to_codec_bytes: Values :Codec: g729r8 pre-ietf ptime :30, codecbytes: 30 Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sipSPI_ipip_update_codec_params_in_channelInfo: Adding negotiated codec 0 ptype 4 time 30, bytes 30 as channel 2 mline 1 ss 1 10.30.0.7:39554 Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Error/sipSPI_ipip_update_codec_params_in_channelInfo: failed to update call entry Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Hndl ptype 101 mline 1 Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sipSPI_ipip_update_dynamic_codec_params: Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sipSPI_ipip_upd_2833_dtmf_params: Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Hndl ptype 13 mline 1 Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Selecting codec No Codec Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Error/sipSPI_ipip_update_call_entry: failed to update call entry Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Copy sdp to channel- AFTER CODEC FILTERING: ccb->pld.ipip_caps.codecInfo[0].codec = 5 Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Copy sdp to channel- AFTER CODEC FILTERING: ccb->pld.ipip_caps.codecInfo[1].codec = 16 Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Copy sdp to channel- AFTER CODEC FILTERING: ccb->pld.ipip_caps.codecInfo[2].codec = 0 Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Copy sdp to channel- AFTER CODEC FILTERING: ccb->pld.ipip_caps.codecInfo[3].codec = -1 Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: srcChannelID = -1, dstChannelID = 5 Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Media/sipSPIDisplayStreamInfo: Stream type : voice-only Media line : 1 State : STREAM_ADDING (2) Stream address type : 1 Callid : 5 Peer Callid : -1 RTP/SRTP Negotiated : 8 Negotiated Codec : g711ulaw, bytes :160 Nego. Codec payload : 0 (tx), 0 (rx) Negotiated DTMF relay : inband-voice Negotiated NTE payload : 0 (tx), 0 (rx) Negotiated CN payload : 13 Media Srce Addr/Port : [10.244.3.1]:0 Media Dest Addr/Port : [10.30.0.7]:39554 Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sipSPI_ipip_calculate_channel_count: Number of streams to report = 1 Aug 12 12:49:10.274: //-1/xxxxxxxxxxxx/SIP/Error/sipSPI_ipip_set_channel_count: Unable to set CHANNEL_COUNT for callid 5 Aug 12 12:49:10.274: //5/E39C859F800E/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. Aug 12 12:49:10.274: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:S_SIP_IWF_SDP_RCVD_AWAIT_PEER_EVENT Aug 12 12:49:10.274: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: OA:next_state:S_SIP_EARLY_DIALOG_OFFER_RCVD Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Media/sipSPIUpdCallWithSdpInfo: Stream type : voice-only Media line : 1 State : STREAM_ADDING (2) Stream address type : 1 Callid : 5 Negotiated Codec : g711ulaw, bytes :160 Nego. Codec payload : 0 (tx), 0 (rx) Negotiated DTMF relay : inband-voice Negotiated NTE payload : 0 (tx), 0 (rx) Negotiated CN payload : 13 Media Srce Addr/Port : [10.244.3.1]:0 Media Dest Addr/Port : [10.30.0.7]:39554 Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sipSPIHandleInviteMedia: Negotiated Codec : g711ulaw, bytes :160 Preferred Codec : g711ulaw, bytes :160 Preferred DTMF relay 1 : 0 Preferred DTMF relay 2 : 0 Negotiated DTMF relay : 0 Preferred and Negotiated NTE payloads: 98 0 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 Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sipSPIDoQoSNegotiationWithMediaLine: QOS negotiation for mline_index 1 Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sipSPIDoStreamQoSNegotiation: Best effort Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sipSPICanSetFallbackFlag: Local Fallback is not active Aug 12 12:49:10.274: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIReserveRtpPort: reserved port 16604 for stream 1 Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sipSPIUpdateSrcSdpFixedPart: Reserving rtp port for stream 1, src_port=16604 Aug 12 12:49:10.274: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetMediaDirectionForStream: Setting Media direction SENDRECV for stream 1 Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sipSPIUpdateSrcSdpVariablePart: Setting stream 1 portnum to 16604 Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sipSPIUpdateSrcSdpVariablePart: SIP update src sdp, negoitated codec 5, payload type 0 Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sipSPIAddBillingInfoToCcb: sipCallId for billing records = MmJjMmNkNjAyOGY5YjkzYjM5ZDYzN2E3YWQ1Njk2YmY. Aug 12 12:49:10.274: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentCPA: No CPA found in inbound container Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sipSPIProcessCPA: No x-cisco-cpa content found Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0 Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sipSPI_ipip_ExtractPassthruCopyListHdrsFromSipContainer: Unsupported header passthru is not configured and no headers are present in hdr_hash_queue Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sipSPI_ipip_IsContentPassthruEnabled: - 0 Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sipSPI_ipip_ExtractPassthruContentFromSipContainer: Passthru Content Not Enabled Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/ccsip_api_call_setup_ind: Unable to add unsupp headers to container Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/ccsip_api_call_setup_ind: Set Protocol information Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/ccsip_ipip_media_service_get_event_data: Event id = 24 Aug 12 12:49:10.274: //5/E39C859F800E/SIP/Info/sipSPI_ipip_antiTrombone: Entered Antitrombone service Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Info/sipSPI_ipip_antiTrombone: Antitrombone service not configured Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Info/sipSPI_ipip_store_channel_info: Store channelInfo in CallInfo Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Info/sipSPI_ipip_store_channel_info: dtmf negotiation done, storing negotiated dtmf = 0, Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Media/sipSPIDisplayStreamInfo: Stream type : voice-only Media line : 1 State : STREAM_ADDING (2) Stream address type : 1 Callid : 5 Peer Callid : -1 RTP/SRTP Negotiated : 8 Negotiated Codec : g711ulaw, bytes :160 Nego. Codec payload : 0 (tx), 0 (rx) Negotiated DTMF relay : inband-voice Negotiated NTE payload : 0 (tx), 0 (rx) Negotiated CN payload : 13 Media Srce Addr/Port : [10.244.3.1]:16604 Media Dest Addr/Port : [10.30.0.7]:39554 Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Info/sipSPI_ipip_calculate_channel_count: Number of streams to report = 1 Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Info/sipSPI_ipip_store_channel_info: Setting CHANNEL_COUNT = 1 for callid 5 Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Info/sipSPIShrlCall: Check peer: 1 for Shared-Line call, callid: 5 Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Info/ccsip_set_bearer_capability: Bearer Capability: Speech (0x00) Aug 12 12:49:10.278: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQSIG: No QSIG Body found in inbound container Aug 12 12:49:10.278: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQ931: No RawMsg Body found in inbound container Aug 12 12:49:10.278: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICreateNewRawMsg: No Data to form The Raw Message Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Info/sipSPIContinueNewMsgInvite: ccsip_api_call_setup_ind returned: SIP_SUCCESS Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 5 to table Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Info/sipSPIUpdateCallEntry: Call 5 set InfoType to SPEECH Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_RESP Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Event/Session-Timer/sipSTSLMain: dir:1, method:102, resp_code:100, container:88C35BC4 Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Info/Session-Timer/sipSTSLValidateSessRefreshMsg: Ignoring 1xx response for session timer processing Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Info/sipSPISendInviteResponse: Associated container=0x88C35BC4 to Invite Response 100 Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Transport/sipSPITransportSendMessage: msg=0x866D7BF8, addr=10.30.0.2, port=5060, sentBy_port=5060, local_addr=10.244.3.1, is_req=0, transport=1, switch=0, callBack=0x0 Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x866D7BF8 to default port=5060 Aug 12 12:49:10.278: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.30.0.2, rport:5060 with laddr:10.244.3.1 Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x866D7BF8 Aug 12 12:49:10.278: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x866D7BF8, addr=10.30.0.2, port=5060, local_addr=10.244.3.1, connId=3 for UDP Aug 12 12:49:10.278: //5/E39C859F800E/SIP/State/sipSPIChangeState: 0x889B72B8 : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_RECD_INVITE, SUBSTATE_NONE) Aug 12 12:49:10.278: //5/E39C859F800E/SIP/Info/sipSPIProcessContactInfo: Previous Hop 10.30.0.2:5060 Aug 12 12:49:10.282: //5/E39C859F800E/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.30.0.2:5060;branch=z9hG4bK-d8754z-89dfab4048c4270b-1---d8754z-;rport From: "TESTE ANGOLA";tag=5982796e To: Date: Tue, 12 Aug 2014 12:49:10 GMT Call-ID: MmJjMmNkNjAyOGY5YjkzYjM5ZDYzN2E3YWQ1Njk2YmY. CSeq: 1 INVITE Allow-Events: telephone-event Server: Cisco-SIPGateway/IOS-12.x Content-Length: 0 Aug 12 12:49:10.282: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_PROCEEDING Aug 12 12:49:10.286: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler: switch(ev.ev_id: 176) Aug 12 12:49:10.286: //5/E39C859F800E/SIP/Info/ccsip_event_handler: Current mode is SIP-TDM Aug 12 12:49:10.286: //5/E39C859F800E/SIP/Info/ccsip_iwf_handle_peer_event: Aug 12 12:49:10.286: //5/E39C859F800E/SIP/Info/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 1, Event Id: 176 Aug 12 12:49:10.286: //5/E39C859F800E/SIP/Info/ccsip_iwf_process_event: Aug 12 12:49:10.286: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_default_early_dialog_container, cur_state:S_SIP_IWF_SDP_RCVD_AWAIT_PEER_EVENT, event:E_SIP_IWF_EV_SET_MODE Aug 12 12:49:10.286: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Aug 12 12:49:10.286: //5/E39C859F800E/SIP/Info/ccsip_get_int_type_frm_set_mode_ev: Aug 12 12:49:10.286: //5/E39C859F800E/SIP/Info/is_mode_sip_sip_md: Aug 12 12:49:10.286: //5/E39C859F800E/SIP/Info/ccsip_get_int_type_frm_set_mode_ev: Aug 12 12:49:10.286: //5/E39C859F800E/SIP/Info/is_mode_sip_sip_ed: Aug 12 12:49:10.286: //5/E39C859F800E/SIP/Info/ccsip_get_int_type_frm_set_mode_ev: Aug 12 12:49:10.286: //5/E39C859F800E/SIP/Info/is_mode_sip_h32x_in_set_mode: Aug 12 12:49:10.286: //5/E39C859F800E/SIP/Info/ccsip_get_int_type_frm_set_mode_ev: Aug 12 12:49:10.286: //5/E39C859F800E/SIP/Info/is_mode_sip_h323_in_set_mode: te-Party-ID: "Assistente 1" ;party=called;screen=no;privacy=off Contact: Server: Cisco-SIPGateway/IOS-12.x Content-Length: 0 Aug 12 12:49:11.230: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [10.30.0.2]:5060, local_address:[10.244.3.1] Aug 12 12:49:11.230: //5/E39C859F800E/SIP/Info/sipSPIResendInviteResponse: resending 180 response due to no PRACK Aug 12 12:49:11.230: //5/E39C859F800E/SIP/Event/sipSPICreateRpid: Received Octet3A=0x00 -> Setting ;screen=no ;privacy=off Aug 12 12:49:11.230: //5/E39C859F800E/SIP/Info/sipSPISendInviteResponse: Associated container=0x88C35C1C to Invite Response 180 Aug 12 12:49:11.230: //5/E39C859F800E/SIP/Transport/sipSPISendInviteResponse: Sending 180 Response to the Transport Layer Aug 12 12:49:11.230: //5/E39C859F800E/SIP/Transport/sipSPITransportSendMessage: msg=0x8660C64C, addr=10.30.0.2, port=5060, sentBy_port=5060, local_addr=10.244.3.1, is_req=0, transport=1, switch=0, callBack=0x0 Aug 12 12:49:11.230: //5/E39C859F800E/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Aug 12 12:49:11.230: //5/E39C859F800E/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Aug 12 12:49:11.230: //5/E39C859F800E/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x8660C64C to default port=5060 Aug 12 12:49:11.230: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.30.0.2, rport:5060 with laddr:10.244.3.1 Aug 12 12:49:11.230: //5/E39C859F800E/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x8660C64C Aug 12 12:49:11.230: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x8660C64C, addr=10.30.0.2, port=5060, local_addr=10.244.3.1, connId=3 for UDP Aug 12 12:49:11.230: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Aug 12 12:49:11.230: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Aug 12 12:49:11.230: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: PRACK sip:103@10.244.3.1:5060 SIP/2.0 Via: SIP/2.0/UDP 10.30.0.2:5060;branch=z9hG4bK-d8754z-6432be76bd80047e-1---d8754z-;rport Max-Forwards: 70 Record-Route: Contact: To: ;tag=5299428-7 From: "TESTE ANGOLA";tag=5982796e Call-ID: MmJjMmNkNjAyOGY5YjkzYjM5ZDYzN2E3YWQ1Njk2YmY. CSeq: 2 PRACK User-Agent: Aastra MX-ONE SN/13.211.3 RAck: 8682 1 INVITE Content-Length: 0 Aug 12 12:49:11.230: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog Aug 12 12:49:11.230: //5/E39C859F800E/SIP/Info/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x889B72B8 Aug 12 12:49:11.230: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.30.0.2,Port 5060, Transport 1, SentBy Port 5060 Aug 12 12:49:11.230: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone WAT to SIP default timezone = GMT Aug 12 12:49:11.234: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.30.0.2,Port 5060, Transport 1, SentBy Port 5060 Aug 12 12:49:11.234: //5/E39C859F800E/SIP/Info/act_recdinvite_new_message_request: Transaction Complete. Lock on Facilities released. Aug 12 12:49:11.234: //5/E39C859F800E/SIP/Transport/sipSPISendPrackResponse: Sending PRACK Response to the transport layer Aug 12 12:49:11.234: //5/E39C859F800E/SIP/Transport/sipSPITransportSendMessage: msg=0x866D7BF8, addr=10.30.0.2, port=5060, sentBy_port=5060, local_addr=10.244.3.1, is_req=0, transport=1, switch=0, callBack=0x0 Aug 12 12:49:11.234: //5/E39C859F800E/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Aug 12 12:49:11.234: //5/E39C859F800E/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Aug 12 12:49:11.234: //5/E39C859F800E/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x866D7BF8 to default port=5060 Aug 12 12:49:11.234: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.30.0.2, rport:5060 with laddr:10.244.3.1 Aug 12 12:49:11.234: //5/E39C859F800E/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x866D7BF8 Aug 12 12:49:11.262: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x8660C64C, addr=10.30.0.2, port=5060, local_addr=10.244.3.1, connId=3 for UDP Aug 12 12:49:11.262: //5/E39C859F800E/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.30.0.2:5060;branch=z9hG4bK-d8754z-6432be76bd80047e-1---d8754z-;rport From: "TESTE ANGOLA";tag=5982796e To: ;tag=5299428-7 Date: Tue, 12 Aug 2014 12:49:11 GMT Call-ID: MmJjMmNkNjAyOGY5YjkzYjM5ZDYzN2E3YWQ1Njk2YmY. Server: Cisco-SIPGateway/IOS-12.x CSeq: 2 PRACK Content-Length: 0 Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Info/ccsip_query_codec_info: Negotiated codec = 5 Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Info/sipSPI_ipip_codec_byte_transrating: NOT SIP-SIP CALL. Will be addressed in future. Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Info/ccsip_bridge: confID = 3, srcCallID = 5, dstCallID = 6 Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Info/sipSPIUupdateCcCallIds: Old src/dest ccCallids: -1/-1, new src/dest ccCallids: 5/6 Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Info/sipSPIUupdateCcCallIds: Old streamcallid=5, new streamcallid=5 Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Info/ccsip_gw_set_sipspi_mode: Setting SPI mode to SIP-TDM Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Info/ccsip_iwf_handle_generic_event: Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Info/ccsip_iwf_process_event: Aug 12 12:49:14.442: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_sccp_early_dialog_container, cur_state:S_SIP_IWF_SDP_RCVD_AWAIT_PEER_EVENT, event:E_SIP_IWF_EV_CALL_BRIDGE Aug 12 12:49:14.442: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Info/ccsip_iwf_process_event: IWF - cnfsm ret 2 Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Info/ccsip_bridge: xcoder_attached = 0, xmitFunc = -2139178220, ccb xmitFunc = -2139178220 Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Info/ccsip_spi_check_call_locally_held: CCSIP: call is locally noton-hold Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Media/sipSPIAddStream: Adding stream 1 of type voice-only (callid 5) to the VOIP RTP library Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Info/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Info/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.244.3.1 Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1 Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info laddr = 10.244.3.1, lport = 16604, raddr = 10.30.0.7, rport=39554, do_rtcp=TRUE src_callid = 5, dest_callid = 6, stream type = voice-only, stream direction = SENDRECV media_ip_addr = 10.30.0.7, vrf tableid = 0 media_addr_type = 1 Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Media/sipSPIUpdateRtcpSession: No rtp session, creating a new one Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Info/sipSPICreateRtpSession: sess: 866953BC do_rtcp:1 Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Media/sipSPICreateRtpSession: stun is disabled Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Info/sipSPICreateAndStartRtpTimer: Media Inactivity Timer is disabled. Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Info/sipSPI_ipip_is_escalation: local channels = 1, peer channels = 0 Aug 12 12:49:14.442: //5/E39C859F800E/SIP/Media/sipSPIGetNewLocalMediaDirection: New Remote Media Direction = SENDRECV Present Local Media Direction = SENDRECV New Local Media Direction = SENDRECV retVal = 0 Aug 12 12:49:14.442: //5/E39C859F800E/SIP/State/sipSPIChangeStreamState: Stream (callid = 5) State changed from (STREAM_ADDING) to (STREAM_ACTIVE) Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/ccsip_iwf_handle_peer_event: Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 3, Event Id: 25 Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/ccsip_iwf_process_event: Aug 12 12:49:14.446: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_sccp_early_dialog_container, cur_state:S_SIP_IWF_SDP_RCVD_AWAIT_PEER_EVENT, event:E_SIP_IWF_EV_PEER_CAPS Aug 12 12:49:14.446: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/is_mode_sip_sccp_do_video: Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/sip_iwf_def_peer_caps_ind_hdlr: Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/ccsip_get_rtcp_session_parameters: CURRENT VALUES: stream_callid=5, current_seq_num=0x17B6 Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/ccsip_get_rtcp_session_parameters: NEW VALUES: stream_callid=5, current_seq_num=0xB79 Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/sip_iwf_def_process_caps_ind: Load DSP with negotiated codec: g711ulaw, Bytes=160 Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/sip_iwf_def_process_caps_ind: Set forking flag to 0x0 Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/sipSPISetDTMFRelayMode: Set DSP for dtmf-relay = CC_CAP_DTMF_RELAY_INBAND_VOICE_AND_OOB Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/sip_set_modem_caps: Preferred (or the one that came from DSM) modem relay=0, from CLI config=0 Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/sipSPIGetModemInfoPerCall: peer_callID=6 Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/sip_set_modem_caps: Disabling Modem Relay... Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/sip_generate_sdp_xcaps_list: Modem Relay and T38 disabled. X-cap not needed Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/sip_set_modem_caps: Negotiation already Done. Set negotiated Modem caps and generate SDP Xcap list Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/sip_set_modem_caps: Modem Relay & Passthru both disabled Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/sip_set_modem_caps: nse payload = 0, ptru mode = 0, ptru-codec=0, redundancy=0, xid=0, relay=0, sprt-retry=12, latecncy=200, compres-dir=3, dict=1024, strnlen=32 Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Media/sipSPISetStreamInfo: 1 Active Streams Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Media/sipSPISetStreamInfo: Adding stream type (voice-only) from media line 1 codec g711ulaw Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Media/sipSPISetStreamInfo: caps.stream_count=1,caps.stream[0].stream_type=0x1, caps.stream_list.xmitFunc= Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Media/sipSPISetStreamInfo: voip_rtp_xmit, caps.stream_list.context= Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Media/sipSPISetStreamInfo: 0x86694F80 (gccb) Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/sip_iwf_def_process_caps_ind: Load DSP with codec : g711ulaw, Bytes=160, payload = 0 Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/sip_iwf_def_process_caps_ind: ccsip_caps_ind: ccb->pld.flags_ipip = 0x203 Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/sip_iwf_def_process_caps_ind: Calling cc_api_caps_ack() Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/ccsip_ipip_media_service_get_event_data: Event id = 7 Aug 12 12:49:14.446: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IPIPMS:cur_container:ccsip_ipip_media_service_main_container, cur_state:S_IPIP_MEDIA_SERV_STATE_IDLE, event:E_IPIP_MEDIA_SERV_EV_PEER_CAPS_IND Aug 12 12:49:14.446: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:CNFSM_NO_STATE_CHANGE Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/ccsip_iwf_handle_peer_event: Return value : SIP_IWF_SUCCESS Aug 12 12:49:14.446: //5/E39C859F800E/SIP/Info/ccsip_iwf_map_cc_return_code: Mapping SIP_IWF_SUCCESS Aug 12 12:49:14.450: //5/E39C859F800E/SIP/Info/ccsip_iwf_handle_peer_event: Aug 12 12:49:14.450: //5/E39C859F800E/SIP/Info/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 3, Event Id: 26 Aug 12 12:49:14.450: //5/E39C859F800E/SIP/Info/ccsip_iwf_process_event: Aug 12 12:49:14.450: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_sccp_early_dialog_container, cur_state:S_SIP_IWF_SDP_RCVD_AWAIT_PEER_EVENT, event:E_SIP_IWF_EV_PEER_CAPS_ACK, Aug 12 12:49:14.450: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Aug 12 12:49:14.450: //5/E39C859F800E/SIP/Info/sip_iwf_def_peer_caps_ack_hdlr: Aug 12 12:49:14.450: //5/E39C859F800E/SIP/Info/sip_iwf_tdm_process_caps_ack: Set forking flag to 0x0 Aug 12 12:49:14.450: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:CNFSM_NO_STATE_CHANGE Aug 12 12:49:14.450: //5/E39C859F800E/SIP/Info/ccsip_iwf_handle_peer_event: Return value : SIP_IWF_SUCCESS Aug 12 12:49:14.450: //5/E39C859F800E/SIP/Info/ccsip_iwf_map_cc_return_code: Mapping SIP_IWF_SUCCESS Aug 12 12:49:14.450: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_call_connect: CCSIP_CALL_CONNECT: ccb ptr 889B72B8 Aug 12 12:49:14.450: //5/E39C859F800E/SIP/Info/ccsip_iwf_handle_generic_event: Aug 12 12:49:14.450: //5/E39C859F800E/SIP/Info/ccsip_iwf_process_event: Aug 12 12:49:14.450: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_sccp_early_dialog_container, cur_state:S_SIP_IWF_SDP_RCVD_AWAIT_PEER_EVENT, event:E_SIP_IWF_EV_CALL_CONNECT Aug 12 12:49:14.450: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Aug 12 12:49:14.450: //5/E39C859F800E/SIP/Info/sip_iwf_common_call_connect_hdlr: Aug 12 12:49:14.450: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:CNFSM_NO_STATE_CHANGE Aug 12 12:49:14.450: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_call_connect: CCSIP_CALL_CONNECT: app_diaplay_name[Assistente 1] app_display_num[103] Aug 12 12:49:14.450: //5/E39C859F800E/SIP/Info/ccsip_call_connect: CCSIP_CALL_CONNECT : KPML_CONFIGURED[FALSE] collect_digits[103] calledNumber[103] display_name[Assistente 1] display_num[103] Aug 12 12:49:14.450: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_CONNECT Aug 12 12:49:14.450: //-1/xxxxxxxxxxxx/SIP/Error/ccsip_call_service_msg: ccb NULL, unable to update the callinfo ui parameters Aug 12 12:49:14.454: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_MEDIA_EVENT Aug 12 12:49:14.458: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 7 Aug 12 12:49:14.458: //5/E39C859F800E/SIP/Info/sipSPIAddCiscoGcid: Gcid value not set - not adding header. Aug 12 12:49:14.458: //5/E39C859F800E/SIP/Error/sipSPI_ipip_set_history_info_header: Not SIP2SIP mode Aug 12 12:49:14.458: //5/E39C859F800E/SIP/Info/sipSPIQoSRevertBW: Entry Aug 12 12:49:14.458: //5/E39C859F800E/SIP/Info/preprocessConnect: Write sdp_info into msg_body Aug 12 12:49:14.458: //5/E39C859F800E/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_RESP Aug 12 12:49:14.458: //5/E39C859F800E/SIP/Event/Session-Timer/sipSTSLMain: dir:1, method:102, resp_code:200, container:88C35FE4 Aug 12 12:49:14.458: //5/E39C859F800E/SIP/Info/Session-Timer/sipSTSLSRRespSend: Session expires header is received in the request, starting the session timer Aug 12 12:49:14.458: //5/E39C859F800E/SIP/Info/Session-Timer/sipSTSLStartSessionTimer: Started Session Expiry Timer with duration:1768000 Aug 12 12:49:14.458: //5/E39C859F800E/SIP/Info/Session-Timer/sipSTSLMain: SE: 1800;refresher:uas peer refresher:none, flags:1, posted event:E_STSL_INVALID_PEER_EVENT, reason:4 Configured SE:1800, Configured Min-SE:1800 Aug 12 12:49:14.458: //5/E39C859F800E/SIP/Info/ccsip_offer_ans_handle_sent_sdp: Aug 12 12:49:14.458: //5/E39C859F800E/SIP/Info/ccsip_offer_ans_process_event: Aug 12 12:49:14.458: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: OA:cur_container:ccsip_offer_ans_main_container, cur_state:S_SIP_EARLY_DIALOG_OFFER_RCVD, event:E_SIP_INVITE_RESP_SDP_SENT Aug 12 12:49:14.458: //5/E39C859F800E/SIP/Info/ccsip_offer_ans_is_outgoing_invite_resp_answer_valid: - 1 Aug 12 12:49:14.458: //5/E39C859F800E/SIP/Info/ccsip_offer_ans_common_answer_sent_hdlr: Aug 12 12:49:14.458: //5/E39C859F800E/SIP/Info/ccsip_iwf_handle_network_event: Aug 12 12:49:14.458: //5/E39C859F800E/SIP/Info/ccsip_iwf_process_event: Aug 12 12:49:14.458: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_sccp_early_dialog_container, cur_state:S_SIP_IWF_SDP_RCVD_AWAIT_PEER_EVENT, event:E_SIP_IWF_EV_SENT_SDP Aug 12 12:49:14.458: //5/E39C859F800E/SIP/Info/sip_iwf_def_ed_sent_sdp_answer_hdlr: Aug 12 12:49:14.458: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:S_SIP_IWF_SDP_DONE Aug 12 12:49:14.458: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: OA:next_state:S_SIP_EARLY_DIALOG_OFFER_ANSWER_COMPLETE Aug 12 12:49:14.458: //5/E39C859F800E/SIP/Event/sipSPICreateRpid: Received Octet3A=0x00 -> Setting ;screen=no ;privacy=off Aug 12 12:49:14.458: //5/E39C859F800E/SIP/Info/sipSPIAppAddCallInfoUI: callinfo UI update request for callid: 5 Aug 12 12:49:14.462: //5/E39C859F800E/SIP/Info/sipSPISendInviteResponse: Transaction active. Facilities will be queued. SIP: (5) Group (a= group line) attribute, level 65535 instance 1 not found. Aug 12 12:49:14.462: //5/E39C859F800E/SIP/Info/sipSPIGetCallExtensionSupported: anat enabled, src_sdp and dest_sdp available, should be a midcall request Aug 12 12:49:14.462: //5/E39C859F800E/SIP/Info/sipSPISendInviteResponse: Associated container=0x88C35FE4 to Invite Response 200 Aug 12 12:49:14.462: //5/E39C859F800E/SIP/Transport/sipSPISendInviteResponse: Sending 200OK Response to the Transport Layer Aug 12 12:49:14.462: //5/E39C859F800E/SIP/Transport/sipSPITransportSendMessage: msg=0x8660C64C, addr=10.30.0.2, port=5060, sentBy_port=5060, local_addr=10.244.3.1, is_req=0, transport=1, switch=0, callBack=0x814A96B4 Aug 12 12:49:14.462: //5/E39C859F800E/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Aug 12 12:49:14.462: //5/E39C859F800E/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Aug 12 12:49:14.462: //5/E39C859F800E/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x8660C64C to default port=5060 Aug 12 12:49:14.462: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.30.0.2, rport:5060 with laddr:10.244.3.1 Aug 12 12:49:14.462: //5/E39C859F800E/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x8660C64C Aug 12 12:49:14.462: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x8660C64C, addr=10.30.0.2, port=5060, local_addr=10.244.3.1, connId=3 for UDP Aug 12 12:49:14.462: //5/E39C859F800E/SIP/Info/sentInviteResponse200: Sent 200Ok for Invite in state STATE_SENT_ALERTING Aug 12 12:49:14.462: //-1/xxxxxxxxxxxx/SIP/Info/sentInviteResponse200: Transaction active. Facilities will be queued. Aug 12 12:49:14.462: //5/E39C859F800E/SIP/State/sipSPIChangeState: 0x889B72B8 : State change from (STATE_SENT_ALERTING, SUBSTATE_NONE) to (STATE_SENT_SUCCESS, SUBSTATE_NONE) Aug 12 12:49:14.462: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 29 Aug 12 12:49:14.462: //5/E39C859F800E/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SPI_EVENT Aug 12 12:49:14.462: //5/E39C859F800E/SIP/Info/Session-Timer/sipSTSLMain: SE: 1800;refresher:uas peer refresher:none, flags:1, posted event:E_STSL_INVALID_PEER_EVENT, reason:4 Configured SE:1800, Configured Min-SE:1800 Aug 12 12:49:14.466: //5/E39C859F800E/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.30.0.2:5060;branch=z9hG4bK-d8754z-89dfab4048c4270b-1---d8754z-;rport From: "TESTE ANGOLA";tag=5982796e To: ;tag=5299428-7 Date: Tue, 12 Aug 2014 12:49:11 GMT Call-ID: MmJjMmNkNjAyOGY5YjkzYjM5ZDYzN2E3YWQ1Njk2YmY. CSeq: 1 INVITE Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER Allow-Events: telephone-event Remote-Party-ID: "Assistente 1" ;party=called;screen=no;privacy=off Contact: Supported: replaces Supported: sdp-anat Server: Cisco-SIPGateway/IOS-12.x Require: timer Session-Expires: 1800;refresher=uac Supported: timer Content-Type: application/sdp Content-Disposition: session;handling=required Content-Length: 209 v=0 o=CiscoSystemsSIP-GW-UserAgent 4782 2528 IN IP4 10.244.3.1 s=SIP Call c=IN IP4 10.244.3.1 t=0 0 m=audio 16604 RTP/AVP 0 13 c=IN IP4 10.244.3.1 a=rtpmap:0 PCMU/8000 a=rtpmap:13 CN/8000 a=ptime:20 Aug 12 12:49:14.906: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [10.30.0.2]:5060, local_address:[10.244.3.1] Aug 12 12:49:14.906: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Aug 12 12:49:14.906: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Aug 12 12:49:14.906: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: ACK sip:103@10.244.3.1:5060 SIP/2.0 Via: SIP/2.0/UDP 10.30.0.2:5060;branch=z9hG4bK-d8754z-5662f57d76179718-1---d8754z-;rport Max-Forwards: 70 Record-Route: Contact: To: ;tag=5299428-7 From: "TESTE ANGOLA";tag=5982796e Call-ID: MmJjMmNkNjAyOGY5YjkzYjM5ZDYzN2E3YWQ1Njk2YmY. CSeq: 1 ACK User-Agent: Aastra MX-ONE SN/13.211.3 Content-Length: 0 Aug 12 12:49:14.906: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog Aug 12 12:49:14.910: //5/E39C859F800E/SIP/Info/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x889B72B8 Aug 12 12:49:14.910: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.30.0.2,Port 5060, Transport 1, SentBy Port 5060 Aug 12 12:49:14.910: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone WAT to SIP default timezone = GMT Aug 12 12:49:14.910: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.30.0.2,Port 5060, Transport 1, SentBy Port 5060 Aug 12 12:49:14.910: //5/E39C859F800E/SIP/Info/act_sentsucc_new_message_request: Transaction Complete. Lock on Facilities released. Aug 12 12:49:14.910: //5/E39C859F800E/SIP/State/sipSPIChangeState: 0x889B72B8 : State change from (STATE_SENT_SUCCESS, SUBSTATE_NONE) to (STATE_ACTIVE, SUBSTATE_NONE) Aug 12 12:49:14.910: //5/E39C859F800E/SIP/Call/sipSPICallInfo: The Call Setup Information is: Call Control Block (CCB) : 0x889B72B8 State of The Call : STATE_ACTIVE TCP Sockets Used : NO Calling Number : 726 Called Number : 103 Source IP Address (Sig ): 10.244.3.1 Destn SIP Req Addr:Port : 10.30.0.2:5060 Destn SIP Resp Addr:Port : 10.30.0.2:5060 Destination Name : 10.30.0.2 Aug 12 12:49:14.910: //5/E39C859F800E/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 : 0 Dtmf-relay Payload : 0 (tx), 0 (rx) Source IP Address (Media): 10.244.3.1 Source IP Port (Media): 16604 Destn IP Address (Media): 10.30.0.7 Destn IP Port (Media): 39554 Orig Destn IP Address:Port (Media): [ - ]:0 Aug 12 12:49:14.910: //5/E39C859F800E/SIP/Info/sipSPICreateAndStartRtpTimer: Media Inactivity Timer is disabled. Aug 12 12:49:14.910: //5/E39C859F800E/SIP/Info/sipSPIProcessHoldTimerForCall: Media IP Addr 10.30.0.7, RTCP Type 3 Aug 12 12:49:14.910: //5/E39C859F800E/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer Aug 12 12:49:14.910: //5/E39C859F800E/SIP/Info/sipSPIOptionsPing: Session Timer negotiated, not doing Options Ping Aug 12 12:49:14.910: //5/E39C859F800E/SIP/Info/ccsip_offer_ans_handle_call_active: Aug 12 12:49:14.910: //5/E39C859F800E/SIP/Info/ccsip_offer_ans_process_event: Aug 12 12:49:14.910: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: OA:cur_container:ccsip_offer_ans_main_container, cur_state:S_SIP_EARLY_DIALOG_OFFER_ANSWER_COMPLETE, event:E_SIP_DIALOG_ESTD Aug 12 12:49:14.910: //5/E39C859F800E/SIP/Info/ccsip_offer_ans_dialog_established_hdlr: Aug 12 12:49:14.910: //5/E39C859F800E/SIP/Info/ccsip_iwf_handle_generic_event: Aug 12 12:49:14.910: //5/E39C859F800E/SIP/Info/ccsip_iwf_process_event: Aug 12 12:49:14.910: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_sccp_early_dialog_container, cur_state:S_SIP_IWF_SDP_DONE, event:E_SIP_IWF_EV_CALL_ACTIVE Aug 12 12:49:14.910: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Aug 12 12:49:14.910: //5/E39C859F800E/SIP/Info/is_mode_sip_sip: Aug 12 12:49:14.910: //5/E39C859F800E/SIP/Info/is_mode_sip_h323: Aug 12 12:49:14.910: //5/E39C859F800E/SIP/Info/is_mode_sip_h32x: Aug 12 12:49:14.910: //5/E39C859F800E/SIP/Info/ccsip_iwf_set_tdm_ip_call_active: Aug 12 12:49:14.910: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_sccp_mid_dialog_container Aug 12 12:49:14.910: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:CNFSM_NO_STATE_CHANGE Aug 12 12:49:14.910: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: OA:next_state:S_SIP_MID_DIALOG_IDLE Aug 12 12:49:14.910: //5/E39C859F800E/SIP/Info/ccsip_api_update_allowed: UPDATE(2) allowed Aug 12 12:49:14.910: //5/E39C859F800E/SIP/Info/ccsip_offer_ans_handle_update_allowed: Aug 12 12:49:14.910: //5/E39C859F800E/SIP/Info/ccsip_ipip_media_service_get_event_data: Event id = 21 Aug 12 12:49:14.910: //5/E39C859F800E/SIP/State/ccsip_cnfsm_debugs: IPIPMS:cur_container:ccsip_ipip_media_service_main_container, cur_state:S_IPIP_MEDIA_SERV_STATE_IDLE, event:E_IPIP_MEDIA_SERV_EV_TRIGGER_LOCAL_FA_MEDIA Aug 12 12:49:18.158: //5/E39C859F800E/SIP/Info/ccsip_indicate_rt_packet_stats: Processing stats for callid=5, proc_id=9 Aug 12 12:49:20.310: //5/E39C859F800E/SIP/Media/sipSPIUpdateRtpSession: stun is disabled for stream:866D9004 Aug 12 12:49:20.310: //5/E39C859F800E/SIP/Info/ccsip_call_statistics: Requesting stats for callid=5 Aug 12 12:49:20.310: //5/E39C859F800E/SIP/Info/ccsip_ipip_media_service_get_event_data: Event id = 26 Aug 12 12:49:20.310: //5/E39C859F800E/SIP/Info/sipSPI_ipip_antiTrombone: Entered Antitrombone service Aug 12 12:49:20.310: //5/E39C859F800E/SIP/Info/sipSPI_ipip_antiTrombone: Antitrombone service not configured Aug 12 12:49:20.310: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT Aug 12 12:49:20.314: //5/E39C859F800E/SIP/Info/ccsip_indicate_rt_packet_stats: Processing stats for callid=5, proc_id=1 Aug 12 12:49:20.314: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 8 Aug 12 12:49:20.314: //5/E39C859F800E/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer Aug 12 12:49:20.314: //5/E39C859F800E/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer Aug 12 12:49:20.314: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddRouteHeaders: status = TRUE Route: Aug 12 12:49:20.314: //5/E39C859F800E/SIP/Info/sipSPISendBye: Associated container=0x88C3574C to Bye Aug 12 12:49:20.314: //5/E39C859F800E/SIP/Transport/sipSPISendBye: Sending BYE to the transport layer Aug 12 12:49:20.318: //5/E39C859F800E/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE Aug 12 12:49:20.318: //5/E39C859F800E/SIP/Transport/sipSPITransportSendMessage: msg=0x8660C64C, addr=10.30.0.2, port=5060, sentBy_port=0, local_addr=10.244.3.1, is_req=1, transport=1, switch=0, callBack=0x814A9A3C Aug 12 12:49:20.318: //5/E39C859F800E/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Aug 12 12:49:20.318: //5/E39C859F800E/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Aug 12 12:49:20.318: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.30.0.2, rport:5060 with laddr:10.244.3.1 Aug 12 12:49:20.318: //5/E39C859F800E/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x8660C64C Aug 12 12:49:20.318: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x8660C64C, addr=10.30.0.2, port=5060, local_addr=10.244.3.1, connId=3 for UDP Aug 12 12:49:20.318: //5/E39C859F800E/SIP/Info/sentByeDisconnecting: Sent Bye Request, starting DisconnectTimer Aug 12 12:49:20.318: //5/E39C859F800E/SIP/State/sipSPIChangeState: 0x889B72B8 : State change from (STATE_ACTIVE, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE) Aug 12 12:49:20.318: //5/E39C859F800E/SIP/Msg/ccsipDisplayMsg: Sent: BYE sip:726@10.30.0.2:5060 SIP/2.0 Via: SIP/2.0/UDP 10.244.3.1:5060;branch=z9hG4bK4120B From: ;tag=5299428-7 To: "TESTE ANGOLA";tag=5982796e Date: Tue, 12 Aug 2014 12:49:14 GMT Call-ID: MmJjMmNkNjAyOGY5YjkzYjM5ZDYzN2E3YWQ1Njk2YmY. User-Agent: Cisco-SIPGateway/IOS-12.x Max-Forwards: 70 Route: Timestamp: 1407847760 CSeq: 101 BYE Reason: Q.850;cause=16 P-RTP-Stat: PS=285,OS=45600,PR=190,OR=29764,PL=0,JI=0,LA=0,DU=5 Content-Length: 0 Aug 12 12:49:20.702: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [10.30.0.2]:5060, local_address:[10.244.3.1] Aug 12 12:49:20.702: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Aug 12 12:49:20.702: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Aug 12 12:49:20.702: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog Aug 12 12:49:20.702: //5/E39C859F800E/SIP/Info/sipSPIMatchRespToReqTran: removing unneeded z9hG4bK4120B from via branch list Aug 12 12:49:20.702: //5/E39C859F800E/SIP/Info/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x889B72B8 Aug 12 12:49:20.706: //5/E39C859F800E/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.244.3.1:5060;branch=z9hG4bK4120B Record-Route: Contact: To: "TESTE ANGOLA";tag=5982796e From: ;tag=5299428-7 Call-ID: MmJjMmNkNjAyOGY5YjkzYjM5ZDYzN2E3YWQ1Njk2YmY. CSeq: 101 BYE User-Agent: Aastra MX-ONE SN/13.211.3 Content-Length: 0 Aug 12 12:49:20.706: //5/E39C859F800E/SIP/Info/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX Aug 12 12:49:20.706: //5/E39C859F800E/SIP/Info/sipSPIIcpifUpdate: CallState: 4 Playout: 820 DiscTime:8662139 ConnTime 8661514 Aug 12 12:49:20.706: //5/E39C859F800E/SIP/Media/sipSPIDestroyRtpSession: stream:866D9004 Aug 12 12:49:20.706: //5/E39C859F800E/SIP/State/sipSPIChangeState: 0x889B72B8 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE) Aug 12 12:49:20.706: //5/E39C859F800E/SIP/Call/sipSPICallInfo: The Call Setup Information is: Call Control Block (CCB) : 0x889B72B8 State of The Call : STATE_DEAD TCP Sockets Used : NO Calling Number : 726 Called Number : 103 Source IP Address (Sig ): 10.244.3.1 Destn SIP Req Addr:Port : 10.30.0.2:5060 Destn SIP Resp Addr:Port : 10.30.0.2:5060 Destination Name : 10.30.0.2 Aug 12 12:49:20.706: //5/E39C859F800E/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 : 0 Dtmf-relay Payload : 0 (tx), 0 (rx) Source IP Address (Media): 10.244.3.1 Source IP Port (Media): 16604 Destn IP Address (Media): 10.30.0.7 Destn IP Port (Media): 39554 Orig Destn IP Address:Port (Media): [ - ]:0 Aug 12 12:49:20.706: //5/E39C859F800E/SIP/Call/sipSPICallInfo: Disconnect Cause (CC) : 16 Disconnect Cause (SIP) : 200 Aug 12 12:49:20.706: //5/E39C859F800E/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 5 Aug 12 12:49:20.706: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[9] removed. Aug 12 12:49:20.706: //5/E39C859F800E/SIP/Info/sipSPIUdeleteCcbFromUASReqTable: ****Deleting from UAS Request table. Aug 12 12:49:20.706: //5/E39C859F800E/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x889B72B8 key=MmJjMmNkNjAyOGY5YjkzYjM5ZDYzN2E3YWQ1Njk2YmY.103 Aug 12 12:49:20.706: //5/E39C859F800E/SIP/Info/sipSPIUdeleteCcbFromUASRespTable: ****Deleting from UAS Response table. Aug 12 12:49:20.706: //5/E39C859F800E/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x889B72B8 key=MmJjMmNkNjAyOGY5YjkzYjM5ZDYzN2E3YWQ1Njk2YmY.5299428-7 Aug 12 12:49:20.706: //5/E39C859F800E/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Aug 12 12:49:20.706: //5/E39C859F800E/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Aug 12 12:49:20.706: //5/E39C859F800E/SIP/Info/ccsip_offer_ans_delete: Aug 12 12:49:20.706: //5/E39C859F800E/SIP/Info/ccsip_iwf_delete: Aug 12 12:49:20.706: //5/E39C859F800E/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 889B72B8 Aug 12 12:49:20.706: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[9] CMELDA001#