Dec 27 16:58:53: //731/CBDA7271802A/SIP/Info/verbose/32768/ccsip_indicate_rt_packet_stats: Processing stats for callid=731, proc_id=9 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3B111128 with refCount = 1 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3AFE3CAC with refCount = 1 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [10.97.152.6]:5060, local_address:[10.10.52.1] Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3B111128 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: INVITE sip:service-uri-pickup@10.10.52.1 SIP/2.0 Via: SIP/2.0/UDP 10.97.152.6:5060;branch=z9hG4bK4a78f9ea From: "512" ;tag=b07d47d0f08300c81044efc7-0f4307d8 To: Call-ID: b07d47d0-f0830082-2c1600b9-17743cba@10.97.152.6 Max-Forwards: 70 Date: Tue, 27 Dec 2016 16:58:56 GMT CSeq: 101 INVITE User-Agent: Cisco-CP7821/10.3.1 Contact: Expires: 180 Accept: application/sdp Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE,SUBSCRIBE,INFO Remote-Party-ID: "512" ;party=calling;id-type=subscriber;privacy=off;screen=yes Supported: replaces,join,sdp-anat,norefersub,resource-priority,extended-refer,X-cisco-callinfo,X-cisco-serviceuri,X-cisco-escapecodes,X-cisco-service-control,X-cisco-srtp-fallback,X-cisco-monrec,X-cisco-config,X-cisco-sis-7.0.0,X-cisco-xsi-8.5.1 Allow-Events: kpml,dialog Authorization: Digest username="503",realm="cisco.com",uri="sip:service-uri-pickup@10.10.52.1",response="4fe74f7c84efdb10cf74d565c36447b4",nonce="B323F7A0020700B6",cnonce="54df8566",qop=auth,nc=00000005,algorithm=MD5 Content-Length: 322 Content-Type: application/sdp Content-Disposition: session;handling=optional v=0 o=Cisco-SIPUA 12648 0 IN IP4 10.97.152.6 s=SIP Call t=0 0 m=audio 28968 RTP/AVP 0 8 116 18 101 c=IN IP4 10.97.152.6 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:116 iLBC/8000 a=fmtp:116 mode=20 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x232EF158) with key=[896] to table Dec 27 16:58:56: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init: Dec 27 16:58:56: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init: Dec 27 16:58:56: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised.. Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.97.152.6,Port 5060, Transport 1, SentBy Port 5060vrfid 0 Dec 27 16:58:56: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.10.52.1 for SIP Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.10.52.1 for SIP Dec 27 16:58:56: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 10.10.52.1 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 10.10.52.1 Dec 27 16:58:56: //-1/D334C4B58754/SIP/State/sipSPIChangeState: 0x232EF158 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.97.152.6,Port 5060, Transport 1, SentBy Port 5060vrfid 0 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone EET to SIP default timezone = GMT Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.97.152.6,Port 5060, Transport 1, SentBy Port 5060vrfid 0 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x3AFE3CAC) counter, current msg->refCount = 2 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Error/httpish_msg_free: Freeing NULL pointer! Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/verbose/4096/sipSPIAssignCcbLastRequest: Current ccb(0x232EF158)->last_request = 0x3AFE3CAC, refCount = 2 Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/16384/sipSPICheckIpip: User portion null/non-e164.. DP match skipped Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/2048/sipSPICheckAssertedIdConfig: Dialpeer match is not yet done Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/4096/sipSPISetCallingInfo: calling host comes from From: 10.10.52.1 Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/verbose/4096/sipSPIUpdateCallingInfoUsingRpidOrFrom: Updating Calling Info with FROM header data Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/2048/sipSPICheckAssertedIdConfig: Dialpeer match is not yet done Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/critical/4096/sipSPIGetContentGTD: No GTD found in inbound container Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/critical/4096/sipSPIGetContentCSTA: No CSTA found in inbound container Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x232EF158 key=b07d47d0-f0830082-2c1600b9-17743cba@10.97.152.6service-uri-pickup balance 1 Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/8192/sipSPIMatchSrcIpGroup: Match not found on carrier id Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/critical/8192/sipSPIMatchSrcIpGroup: Match not found on Incoming called number: service-uri-pickup Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/critical/8192/sipSPIMatchSrcIpGroup: Match not found on destination pattern: 8152512 Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/12288/ccsipUpdateIncomingCallParams: ccCallInfo: Calling name 512, number 8152512, Calling oct3 0x00, oct_3a 0x80, Called number serviceuripickup Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/verbose/1024/sipSPIGetViaHostInURLFormat: VIA URL:sip:10.97.152.6:5060, Host:10.97.152.6 Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/verbose/67584/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: : 8152512 Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/critical/1024/sipSPIGetFromCalledPartyId: P-Called-Party-ID header not found Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/critical/1024/sipSPIGetPeerByCalledPartyId: P-Called-Party-ID not found or parse error Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/critical/10240/sipSPIGetCallConfig: No match found for P-Called-Party-ID Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/65536/ccsip_sipline_set_vrf: Phone number 8152512 from ccb calling number Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/65536/ccsip_sipline_set_vrf: Obtained phone tag (3) from Dial-peer Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/65536/ccsip_sipline_set_vrf: Got vrf 0 for phone tag 3 Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/8192/sipSPIGetCallConfig: VRF id = 0 Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/2048/sipSPIGetCallConfig: Peer tag 40006 matched for incoming call Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/verbose/1024/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.10.52.1 for SIP Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.10.52.1 for SIP Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 10.10.52.1 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 10.10.52.1 Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/verbose/1024/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/verbose/2048/sipSPIGetCallConfig: Media Antitrombone disabled Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/notify/65536/sipSPISetMediaFlowMode: Forcing the flow mode to FLOW-THROUGH for SIP line Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/8192/sipSPISetMediaFlowMode: Storing the configured mode as FLOW-THROUGH Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/2304/sipSPISetMediaFlowMode: xcoder high-density disabled Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/8192/sipSPISetMediaFlowMode: Flow Mode set to FLOW_THROUGH Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/verbose/4/update_video_params_from_config: Checking Video Type Rate=-1 video_codec_allowed=1F Dec 27 16:58:56: //-1/D334C4B58754/SIP/Media/sipSPICopyStunConfigFromPeerToCCB: STUN Usage is not enabled Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/verbose/12288/sipSPIGetModemInfoPerCall: peer_callID=0 Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/critical/32768/ccsip_ipip_media_forking_update_preferred_codec: MF: Not a Forked SIP leg.. Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/8704/sipSPIGetCallConfig: Incoming: No defer BYE for last call stats Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/verbose/1/ccsip_set_srtp_config: No Srtp configure for this leg. Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/8192/sipSPIGetCallConfig: Media forking disabled Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/34816/ccsip_ipip_media_forking_anchor_leg_config: MF: en_p->encap_s.voIP.voipPeerCfgMediaClass = 0 Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/34816/ccsip_ipip_media_forking_anchor_leg_config: MF: Dial-peer has no media class recorder. Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/36864/sipSPIMFChangeState: MF: Prev state = 0 & New state = -1 Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/32768/ccsip_ipip_media_forking_anchor_leg_reset: MF: Anchor leg config reset done... Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/32768/ccsip_ipip_media_forking_intra_frame_request_config: MF: FIR en_p->encap_s.voIP.voipPeerCfgMediaClass = 0 Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/32768/ccsip_ipip_media_forking_get_forked_leg_config: MF: This leg is not forked call leg. Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/critical/11264/ccsipInitDSCPPolicyInfo: No DSCP Profile configured, No RPH 2 DSCP Mapping and DSCP policing Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/verbose/8192/sipSPIGetCallConfig: Initilise the DSCP policy Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/verbose/8192/sipSPICheckFAAnatAssymetricOrDO2EO: Not a SIP-SIP call or not in FA mode Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/notify/8192/sipSPISetOverlapConfiguration: Overlap signaling: FALSE: Endpt: SIP Line Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/verbose/10240/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0 Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/verbose/2048/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0 Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/notify/10240/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/4096/sipSPIContinueNewMsgInvite: Calling name 512, number 8152512, Calling oct3 0x00, oct_3a 0x80, ext_priv 0x00, Called number service-uri-pickup, oct3 0x00 Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/4096/sipSPIContinueNewMsgInvite: Carrier id code , prev_cid NONE, next_cid NONE, prev_tgrp NONE, next_tgrp NONE Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/critical/10240/sipSPIValidateRequestUri: Not Enabled Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/verbose/65536/ccsip_api_check_dialed_number_for_service_ind: Local Group Pickup: 500 Dec 27 16:58:56: //-1/D334C4B58754/SIP/Info/info/131072/sipSPIRscmsmAvail: Value returned by check is = 0 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/critical/4096/sipSPICheckOutBoundDpProvisioning: Cannot obtain the the header bitmap Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/critical/8192/sipSPI_ipip_IsSDPPassthruEnabled: - 0 Dec 27 16:58:56: //737/D334C4B58754/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_REQ Dec 27 16:58:56: //737/D334C4B58754/SIP/Event/Session-Timer/sipSTSLMain: dir:2, method:102, resp_code:0, container:236312C0 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/notify/8192/Session-Timer/sipSTSLExtractSessionExpiresHdr: Not received session expires header Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/8192/Session-Timer/sipSTSLGetInternalSREvent: E_STSL_INITIAL_SR_REQ Dec 27 16:58:56: //737/D334C4B58754/SIP/Event/Session-Timer/sipSTSLPrintTDContainer: Peer-Event: E_STSL_LEG_BY_LEG, SE Value:0, SE Refresher:none, Min-SE Value:1800, flags:2000 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/8192/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 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/critical/1024/sipSPIProcessHistoryInfoHeader: No HI headers recvd from app container Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/critical/1024/sipSPIProcessDiversionHeader: No diversion headers recvd from app container Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/critical/16384/sipSPIProcessReplacesHeader: No replaces hdr found Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/verbose/1024/sipSPIGetContentCPA: No CPA found in inbound container Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/1024/sipSPIProcessCPA: No x-cisco-cpa content found Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/1/sipSPIDoMediaNegotiation: Number of m-lines = 1 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/1/sipSPIValidateConnectionAddress: Dest port = 28968 SIP: (737) Attribute mid, level 1 instance 1 not found. Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/notify/6/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/513/resolve_media_ip_address_to_bind: peer_tag=40006 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_media_ip_address_to_bind: VRF id = 0 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.10.52.1 for SIP Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.10.52.1 for SIP Dec 27 16:58:56: //737/D334C4B58754/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.10.52.1 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/sipSPICheckDynPayloadUse: Dynamic payload(116) reserved for codec ilbc Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/sipSPICheckDynPayloadUse: Dynamic payload(101) reserved for codec No Codec Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/1/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 96 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/critical/1/sipSPICheckDynPayloadUse: Dynamic payload(101) could not be reserved as its in use by other codec Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/critical/1/sipSPIUpdateDynamicPT: Requested payload-Type (101) is reserved by another application Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/1/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 98 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/1/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 101 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/1/sipSPIAllocateFreeDynamicPT: Allocating free Dynamic Payload : 98 for Codec: Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/notify/1/sipSPIDoAudioNegotiation: Codec (g711ulaw) Negotiation Successful on Static Payload for m-line 1 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/notify/1/sipSPIDoPtimeNegotiation: No ptime present or multiple ptime attributes that can't be handled Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/8/sipSPISetFaxFlags: FAX_PASSTHROUGH = 0, END_FAX_PASSTHROUGH = 0 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/1/sipSPIDoDTMFRelayNegotiation: m-line index 1 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/8193/sip_sdp_get_modem_relay_cap_params: ptype is 0 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/8193/sip_sdp_get_modem_relay_cap_params: ptype is 8 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/8193/sip_sdp_get_modem_relay_cap_params: ptype is 116 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/8193/sip_sdp_get_modem_relay_cap_params: encname is iLBC Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/8193/sip_sdp_get_modem_relay_cap_params: ptype is 18 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/8193/sip_sdp_get_modem_relay_cap_params: ptype is 101 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/8193/sip_sdp_get_modem_relay_cap_params: encname is telephone-event Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/8209/sip_sdp_get_modem_relay_cap_params: mer_dtmf_found 0 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/8209/sip_sdp_get_modem_relay_cap_params: V150 NSE payload = 0, SSE payload = 0, SPRT payload=0 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/critical/8193/sip_select_modem_relay_params: X-tmr not present in SDP. Disable modem relay Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/1/sipSPIGetSDPDirectionAttribute: No direction attribute present or multiple direction attributes that can't be handled for m-line:1 and num-a-lines:0 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/notify/1/sipSPIDoAudioNegotiation: Codec negotiation successful for media line 1 payload_type=0, codec_bytes=160, codec=g711ulaw, dtmf_relay=sip-kpml stream_type=voice-only (0), dest_ip_address=10.97.152.6, dest_port=28968 Dec 27 16:58:56: //737/D334C4B58754/SIP/State/sipSPIChangeStreamState: Stream (callid = -1) State changed from (STREAM_DEAD) to (STREAM_ADDING) Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/sipSPI_Check_If_ICE_Needed: CANDIDATE attribute, level 1 not found. Dec 27 16:58:56: //737/D334C4B58754/SIP/Media/sipSPIUpdCallWithSdpInfo: Preferred Codec : g711ulaw, bytes :160 Preferred DTMF relay : sip-kpml Preferred NTE payload : 98 Early Media : No Delayed Media : No Bridge Done : No New Media : No DSP DNLD Reqd : No Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/notify/6/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/513/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr Dec 27 16:58:56: //737/D334C4B58754/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.10.52.1 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/4096/ccsip_offer_ans_handle_rcvd_sdp: Dec 27 16:58:56: //737/D334C4B58754/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 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/4096/ccsip_offer_ans_is_invite_offer_valid: TRUE Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/4096/ccsip_offer_ans_common_offer_rcvd_hdlr: Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/4096/ccsip_iwf_handle_network_event: Dec 27 16:58:56: //737/D334C4B58754/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 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/4096/sip_iwf_def_ed_rcvd_sdp_hdlr: Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/1/sipSPIAssignStreamCallId: Assigning streamid 737 to stream 1. Old streamid = -1 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/1/sipSPI_initialize_audio_channelInfo_from_sdp: stream_callid = 737, peer_stream_callid = -1 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/8/sipSPI_ipip_init_stream_ex_caps_params: T38 version 0 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/8/sipSPI_ipip_init_stream_ex_caps_params: CCB fax rate 2 ipip_caps rate 14400 SIP: (737) setup attribute, level 1 instance 1 not found. SIP: (737) connection attribute, level 1 instance 1 not found. SIP: (737) Attribute label, level 1 instance 1 not found. SIP: (737) a=framerate attribute, level 1 instance 1 not found. Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/1025/sipSPI_initialize_audio_channelInfo_from_sdp: Populating Address in channelInfo Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/1/sipSPI_initialize_audio_channelInfo_from_sdp: Media dest addr for stream 1='10.97.152.6', port=28968 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/1/sip_iwf_sip_copy_audio_sdp_to_local_channelInfo: Processing Media line = 1; Codec = g711ulaw; PType = 0 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/1/codec_found: Codec to be matched: g711ulaw(5) Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/1/codec_found: Match Found at index 0. Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/1/sip_iwf_sip_copy_audio_sdp_to_local_channelInfo: Add Channel for Codec g711ulaw Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/notify/1/sip_iwf_sip_copy_audio_sdp_to_local_channelInfo: Media negotiation done for m-line=1: negotiated_ptime=0, negotiated_codec_bytes=160 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/1/sipSPI_ipip_update_codec_params_in_stream_channelInfo: Adding negotiated codec g711ulaw ptype 0 time 20, bytes 160 as channel 0 mline 1 ss 1 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/131073/sipSPIBwCacCalcAudioBandwidth: calculated audio bandwidth : codec g711ulaw bw 64000 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/1/sip_iwf_sip_copy_audio_sdp_to_local_channelInfo: Processing Media line = 1; Codec = g711alaw; PType = 8 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/1/codec_found: Codec to be matched: g711alaw(6) Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/notify/1/codec_found: Match Not Found for g711alaw. Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/1/sip_iwf_sip_copy_audio_sdp_to_local_channelInfo: Processing Media line = 1; Codec = ilbc; PType = 116 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/1/codec_found: Codec to be matched: ilbc(33) Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/notify/1/codec_found: Match Not Found for ilbc. Dec 27 16:58:56: //737/D334C4B58754/SIP/Media/sipSPISelectCodecVersion: Codec (g729r8) is not in preferred list Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/notify/1/sipSPI_ipip_update_static_codec_params: An exact codec match not configured, using interoperable codec g729r8 pre-ietf Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/1/sip_iwf_sip_copy_audio_sdp_to_local_channelInfo: Processing Media line = 1; Codec = g729r8 pre-ietf; PType = 18 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/1/codec_found: Codec to be matched: g729r8 pre-ietf(0) Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/notify/1/codec_found: Match Not Found for g729r8 pre-ietf. Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/1/sip_iwf_sip_copy_audio_sdp_to_local_channelInfo: Processing Media line = 1; Codec = No Codec ; PType = 101 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/16/sipSPIGetPreferredSrtpSuiteForBw: Return : 0 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/verbose/16/sipSPIBwCacGetSrtpOverhead: Return: 0 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20 Dec 27 16:58:56: //737/D334C4B58754/SIP/Media/sipSPIDisplayStreamInfo: Stream type : voice-only Media line : 1 State : STREAM_ADDING (2) Stream address type : 1 Callid : 737 Peer Callid : -1 RTP/SRTP Negotiated : 8 Negotiated Codec : g711ulaw, bytes :160 Nego. Codec payload : 0 (tx), 0 (rx) Negotiated DTMF relay : sip-kpml Negotiated NTE payload : 0 (tx), 0 (rx) Negotiated CN payload : 0 Media Srce Addr/Port : [10.10.52.1]:0 Media Dest Addr/Port : [10.97.152.6]:28968 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/4097/sipSPI_ipip_calculate_channel_count: Number of streams to report = 1 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/critical/1/sip_iwf_sip_copy_sdp_to_stream_channelInfo: Not updating call entry. Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/1/sip_iwf_def_ed_rcvd_sdp_hdlr: Setting media_direction to 4 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/131072/sipSPIBwCacUpdateAccountedBw: bwcac update accounted BW Option 0 flow mode flow-through audio bw 80000 bps video bw 0 bps fax bw 0 bps total bw 80000 bps accounted bw 0 bps Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/131072/sipSPIBwCacUpdateInterfaceBw: bwcac acquiring interface Loopback0 bw 80 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/131072/sipSPIBwCacUpdateAccountedBw: bwcac update accounted bw (initial offer) accounted bw set to 80000 Dec 27 16:58:56: //737/D334C4B58754/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:S_SIP_IWF_SDP_RCVD_AWAIT_PEER_EVENT Dec 27 16:58:56: //737/D334C4B58754/SIP/State/ccsip_cnfsm_debugs: OA:next_state:S_SIP_EARLY_DIALOG_OFFER_RCVD Dec 27 16:58:56: //737/D334C4B58754/SIP/Media/sipSPIUpdCallWithSdpInfo: Stream type : voice-only Media line : 1 State : STREAM_ADDING (2) Stream address type : 1 Callid : 737 Negotiated Codec : g711ulaw, bytes :160 Nego. Codec payload : 0 (tx), 0 (rx) Negotiated DTMF relay : sip-kpml Negotiated NTE payload : 0 (tx), 0 (rx) Negotiated CN payload : 0 Media Srce Addr/Port : [10.10.52.1]:0 Media Dest Addr/Port : [10.97.152.6]:28968 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/notify/33/sipSPIHandleInviteMedia: Negotiated Codec : g711ulaw, bytes :160 Preferred Codec : g711ulaw, bytes :160 Preferred DTMF relay 1 : 9 Preferred DTMF relay 2 : 8 Negotiated DTMF relay : 9 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 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/133120/sipSPIBwCacIsDialPeerBwAvailable: bwcac NOP dial-peer bw available tag 40006 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/notify/1/sipSPIBwCacIsInterfaceBwAvailable: bwcac interface bw threshold not configured Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/131072/sipSPIBwCacVerifyBwThreshold: bwcac verify bw threshold, bw available allow call total bw 80000 bps Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/131073/sipSPIDoQoSNegotiationWithMediaLine: QOS negotiation for mline_index 1 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/notify/131072/sipSPIDoStreamQoSNegotiation: Best effort Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/notify/131072/sipSPICanSetFallbackFlag: Local Fallback is not active Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIReserveRtpPort: reserved port 17034 for stream 1 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/1/sipSPIUpdateSrcSdpFixedPart: Reserving rtp port for stream 1, src_port=17034 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/sipSPISetMediaDirectionForStream: Setting Media direction SENDRECV for stream 1 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/1/sipSPIUpdateSrcSdpVariablePart: Setting stream 1 portnum to 17034 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/notify/1/sipSPIUpdateSrcSdpVariablePart: SIP update src sdp, negoitated codec 5, payload type 0 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/4096/sipSPIAddBillingInfoToCcb: sipCallId for billing records = b07d47d0-f0830082-2c1600b9-17743cba@10.97.152.6 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/16384/sipSPI_ipip_AddInvDataToTDContainer: req_uri = sip:service-uri-pickup@10.10.52.1 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/16384/sipSPI_ipip_AddInvDataToTDContainer: to = Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/16384/ccsip_api_call_setup_ind: retVal = 0 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/10240/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/critical/10240/sipSPI_ipip_ExtractPassthruCopyListHdrsFromSipContainer: Unsupported header passthru is not configured and no headers are present in hdr_hash_queue Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/critical/8192/sipSPI_ipip_IsContentPassthruEnabled: - 0 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/notify/8192/sipSPI_ipip_ExtractPassthruContentFromSipContainer: Passthru Content Not Enabled Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/critical/4096/ccsip_api_call_setup_ind: Unable to add unsupp headers to container Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/4096/sipSPICopyAuthenticationHeadersToContainer: sipAuthInfo Initialized Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/notify/4096/sipSPICopyAuthenticationHeadersToContainer: Get Auth Header (Authorization) from packet Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/4096/sipSPICopyAuthenticationHeadersToContainer: Set Authentication Tag to Container Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/4096/ccsip_api_call_setup_ind: Set Protocol information Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/4096/ccsip_ipip_media_service_get_event_data: Event id = 31 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/1/ccsip_api_call_setup_ind: Setting media_direction to 4 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/4096/sipSPI_ipip_store_channel_info: Store channelInfo in CallInfo Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/32/sipSPI_ipip_store_channel_info: dtmf negotiation done, storing negotiated dtmf = 9, Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/2048/sipSPI_ipip_store_config_info: Setting mid_call_config_info = 0x0 for callid = 737SIP/2.0 484 Address Incomplete Via: SIP/2.0/UDP 10.97.152.6:5060;branch=z9hG4bK4a78f9ea From: "512" ;tag=b07d47d0f08300c81044efc7-0f4307d8 To: ;tag=1446D34C-3B3 Date: Tue, 27 Dec 2016 16:58:56 GMT Call-ID: b07d47d0-f0830082-2c1600b9-17743cba@10.97.152.6 CSeq: 101 INVITE Allow-Events: kpml, telephone-event Server: Cisco-SIPGateway/IOS-15.5.3.M4a Reason: Q.850;cause=28 Content-Length: 0 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3B0FBD68 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3AFFF1A4 with refCount = 1 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x252FEFA0 with refCount = 1 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [10.97.152.6]:5060, local_address:[10.10.52.1] Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3AFFF1A4 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: ACK sip:service-uri-pickup@10.10.52.1 SIP/2.0 Via: SIP/2.0/UDP 10.97.152.6:5060;branch=z9hG4bK4a78f9ea From: "512" ;tag=b07d47d0f08300c81044efc7-0f4307d8 To: ;tag=1446D34C-3B3 Call-ID: b07d47d0-f0830082-2c1600b9-17743cba@10.97.152.6 Max-Forwards: 70 Date: Tue, 27 Dec 2016 16:58:56 GMT CSeq: 101 ACK Content-Length: 0 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/4096/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x232EF158 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x252FEFA0) counter, current msg->refCount = 2 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.97.152.6,Port 5060, Transport 1, SentBy Port 5060vrfid 0 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone EET to SIP default timezone = GMT Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.97.152.6,Port 5060, Transport 1, SentBy Port 5060vrfid 0 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/4096/sipSPISetCallingInfo: calling host comes from From: 10.10.52.1 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/4096/sipSPIUpdateCallingInfoUsingRpidOrFrom: Updating Calling Info with FROM header data Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/4096/sipSPISetCommonTimer: Started generic timer type 2 for 240000 millisecs Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/8192/sipSPIDeferCallClose: Not split dataplane, bail Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/8192/sipSPIWaitForStatsBforeCallClose: Not split dataplane, bail Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/4096/sipSPICallCloseAfterFinalStat: sipSPICallCloseAfterFinalStat: Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/12288/sipSPIIcpifUpdate: CallState: 2 Playout: 0 DiscTime:34018601 ConnTime 0 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x3AFE3CAC) counter, current msg->refCount = 1 Dec 27 16:58:56: //737/D334C4B58754/SIP/State/sipSPIChangeState: 0x232EF158 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE) Dec 27 16:58:56: //737/D334C4B58754/SIP/Call/sipSPICallInfo: The Call Setup Information is: Call Control Block (CCB) : 0x0x232EF158 State of The Call : STATE_DEAD TCP Sockets Used : NO Calling Number : 512 Called Number : service-uri-pickup Source IP Address (Sig ): 10.10.52.1 Destn SIP Req Addr:Port : 10.97.152.6:5060 Destn SIP Resp Addr:Port : 10.97.152.6:5060 Destination Name : 10.97.152.6 Dec 27 16:58:56: //737/D334C4B58754/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 : 9 Dtmf-relay Payload : 0 (tx), 0 (rx) Source IP Address (Media): 10.10.52.1 Source IP Port (Media): 17034 Destn IP Address (Media): 10.97.152.6 Destn IP Port (Media): 28968 Orig Destn IP Address:Port (Media): [ - ]:0 Dec 27 16:58:56: //737/D334C4B58754/SIP/Call/sipSPICallInfo: Disconnect Cause (CC) : 28 Disconnect Cause (SIP) : 484 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 2E1 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[896] removed. Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/4096/sipSPIStopCommonTimer: Stopping Generic Timer 2 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x232EF158 key=b07d47d0-f0830082-2c1600b9-17743cba@10.97.152.6service-uri-pickup Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x232EF158 key=b07d47d0-f0830082-2c1600b9-17743cba@10.97.152.61446D34C-3B3 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3AFE3CAC Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Dec 27 16:58:56: //737/D334C4B58754/SIP/Error/sipSPIFlushDeferredQueue: Invalid deferredQueue Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x225FF0A8, addr=10.97.152.6, port=5060, local_addr=10.10.52.1, unregistering context=0x232EF158 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x232EF158 from the connection=0x3F8A5F50 context list Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x252FEFA0) counter, current msg->refCount = 1 Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer Dec 27 16:58:56: //737/D334C4B58754/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x232EF158 Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[896] Dec 27 16:58:56: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x252FEFA0 KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# KOZ01RTP01# Dec 27 16:58:59: //731/CBDA7271802A/SIP/Info/verbose/32768/ccsip_indicate_rt_packet_stats: Processing stats for callid=731, proc_id=9 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[885] removed. Dec 27 16:59:01: //723/B8820D178029/SIP/Info/info/4096/sipSPIStopCommonTimer: Stopping Generic Timer 2 Dec 27 16:59:01: //723/B8820D178029/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x232BB998 key=B8834567-CB7B11E6-8731A4A6-33518F07@10.10.52.1900 Dec 27 16:59:01: //723/B8820D178029/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x232BB998 key=B8834567-CB7B11E6-8731A4A6-33518F07@10.10.52.114462454-A12 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x2227EC48 Dec 27 16:59:01: //723/B8820D178029/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Dec 27 16:59:01: //723/B8820D178029/SIP/Error/sipSPIFlushDeferredQueue: Invalid deferredQueue Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x225FF0A8, addr=10.10.52.1, port=5060, local_addr=10.10.52.1, unregistering context=0x232BB998 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x232BB998 from the connection=0x22600474 context list Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Event/ccsip_api_initiate_subscription_termination: Queued event from SIP SPI : SIPSPI_EV_SUBSCRIPTION_TERMINATED Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Event/ccsip_api_initiate_subscription_termination: Queued event from SIP SPI : SIPSPI_EV_SUBSCRIPTION_TERMINATED Dec 27 16:59:01: //723/B8820D178029/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Dec 27 16:59:01: //723/B8820D178029/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer Dec 27 16:59:01: //723/B8820D178029/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x232BB998 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 7 for event 210 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_spi_process_app_subscribe_event: Event [SIPSPI_EV_SUBSCRIPTION_TERMINATED] received in State [SUBSCRIBE_STATE_ACTIVE] Dec 27 16:59:01: //0/000000000000/SIP/Info/verbose/4096/act_subscription_terminated: Resetting server EDB flag Dec 27 16:59:01: //0/000000000000/SIP/Info/info/4096/sipSPITerminateEvent: 1 Events still active on this Subscription Dialog Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 7 for event 210 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_spi_process_app_subscribe_event: Event [SIPSPI_EV_SUBSCRIPTION_TERMINATED] received in State [SUBSCRIBE_STATE_ACTIVE] Dec 27 16:59:01: //0/000000000000/SIP/Info/verbose/4096/act_subscription_terminated: Resetting Client EDB flag Dec 27 16:59:01: //0/000000000000/SIP/Info/verbose/4096/sipSPIFreeOneEDB: There are 1 EDBs on edbQ Dec 27 16:59:01: //0/000000000000/SIP/Info/verbose/4096/sipSPIFreeOneEDB: DeQ'd EDB(0x2330621C) Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIFreeOneEDB: EnQing EDB(0x2330621C) for reuse Dec 27 16:59:01: //0/000000000000/SIP/Info/verbose/4096/sipSPITerminateEvent: Freeing SCB(0x232FF874), 0 active events present Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[886] removed. Dec 27 16:59:01: //0/000000000000/SIP/Info/verbose/4096/sipSPIRemoveSCBFromServerTable: Removing SCB(0x232FF874) with Key(B8834567-CB7B11E6-8731A4A6-33518F07@10.10.52.114462448-20B8) from Server Table Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x225FF0A8, addr=10.10.52.1, port=5060, local_addr=10.10.52.1, unregistering context=0x232FF874 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x232FF874 from the connection=0x22600474 context list Dec 27 16:59:01: //0/000000000000/SIP/Info/verbose/4096/sipSPIFreeOneSCB: EnQing SCB(0x232FF874) for reuse Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[888] removed. Dec 27 16:59:01: //727/BAF752508737/SIP/Info/info/4096/sipSPIStopCommonTimer: Stopping Generic Timer 2 Dec 27 16:59:01: //727/BAF752508737/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x232F5850 key=BAF7EF11-CB7B11E6-873AA4A6-33518F07@10.10.52.1 Dec 27 16:59:01: //727/BAF752508737/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Dec 27 16:59:01: //727/BAF752508737/SIP/Error/sipSPIFlushDeferredQueue: Invalid deferredQueue Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x225FF0A8, addr=10.97.152.4, port=5060, local_addr=10.10.52.1, unregistering context=0x232F5850 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x232F5850 from the connection=0x22600570 context list Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x2529BEE0 Dec 27 16:59:01: //727/BAF752508737/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Dec 27 16:59:01: //727/BAF752508737/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer Dec 27 16:59:01: //727/BAF752508737/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x232F5850 Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/verbose/4096/ccsip_ipip_media_service_get_event_data: Event id = 18 Dec 27 16:59:01: [0x236319F8]CNFSM: cur_container:ccsip_ipip_media_service_main_container, cur_state:S_IPIP_MEDIA_SERV_STATE_IDLE, event:E_IPIP_MEDIA_SERV_EV_XCODER_RESET_STREAM Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/verbose/256/sipSPIResetXcoder: *****CLEANING UP XCODER RESOURCES***** Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/verbose/256/sipSPIResetXcoder: *****CLEANING UP XCODER RESOURCES***** Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/verbose/256/sipSPIResetXcoder: Xcoder resource already cleaned up Dec 27 16:59:01: [0x236319F8]CNFSM: next_state:S_IPIP_MEDIA_SERV_STATE_IDLE Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/verbose/4096/ccsip_bridge_drop: ReSetting mid call signalling not supported Dec 27 16:59:01: //731/CBDA7271802A/SIP/Media/sipSPIUpdateRtpSession: stun is disabled for stream:3AF92CFC Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/verbose/8192/ccsip_call_statistics: Requesting stats for callid=731 Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/verbose/4096/ccsip_ipip_media_service_get_event_data: Event id = 33 Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/critical/32768/ccsip_ipip_media_forking_post_event: MF: Not a Anchor SIP leg.. Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 8 Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/info/133120/sipSPIBwCacReleaseDialPeerBw: bwcac dial-peer bw 80 Kbps released for tag 9000 active bw 80 Kbps Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/info/131072/sipSPIBwCacReleaseInterfaceBw: bwcac releasing interface Loopback0 bw 80 Kbps Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/info/131072/sipSPIBwCacReleaseAccountedBw: bwcac released accounted bw 80000 bps Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/notify/4096/act_active_disconnect: Disconnect deferred, as stats request pending Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/info/4096/sipSPISetCommonTimer: Started generic timer type 2 for 240000 millisecs Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/verbose/32768/ccsip_indicate_rt_packet_stats: Processing stats for callid=731, proc_id=1 Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/verbose/4096/ccsip_ipip_media_service_get_event_data: Event id = 33 Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/critical/32768/ccsip_ipip_media_forking_post_event: MF: Not a Anchor SIP leg.. Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 8 Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/info/4096/act_active_disconnect: act_active_disconnect: Disconnect now.. no defer BYE.. Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/info/4096/sipSPIStopHoldTimer: Stopping hold timer Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x2529BEE0 with refCount = 1 Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 3 event Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/info/4096/sipSPIStopHoldTimer: Stopping hold timer Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/info/4096/sipSPISendBye: Associated container=0x23630C38 to Bye Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Dec 27 16:59:01: //731/CBDA7271802A/SIP/Transport/sipSPISendBye: Sending BYE to the transport layer Dec 27 16:59:01: //731/CBDA7271802A/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE Dec 27 16:59:01: //731/CBDA7271802A/SIP/Transport/sipSPITransportSendMessage: msg=0x2529BEE0, addr=10.10.52.1, port=5060, sentBy_port=0, local_addr=10.10.52.1, is_req=1, transport=1, switch=0, callBack=0x35F236BC Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Dec 27 16:59:01: //731/CBDA7271802A/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.10.52.1, rport:5060 with laddr:10.10.52.1 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: gcb=0x232CEE80 is already on connection=0x22600474 context_list Dec 27 16:59:01: //731/CBDA7271802A/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x2529BEE0 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x2529BEE0, addr=10.10.52.1, port=5060, local_addr=10.10.52.1, connId=3 vrfid=0 for UDP Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/info/512/sentByeDisconnecting: Sent Bye Request, starting DisconnectTimer Dec 27 16:59:01: //731/CBDA7271802A/SIP/State/sipSPIChangeState: 0x232CEE80 : State change from (STATE_ACTIVE, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE) Dec 27 16:59:01: //731/CBDA7271802A/SIP/Msg/ccsipDisplayMsg: Sent: BYE sip:900@10.10.52.1:5060 SIP/2.0 Via: SIP/2.0/UDP 10.10.52.1:5060;x-route-tag="tgrp:100";branch=z9hG4bK2921720 From: ;tag=1446A314-222D To: ;tag=1446A31C-15B5 Date: Tue, 27 Dec 2016 16:58:44 GMT Call-ID: CBDC4782-CB7B11E6-874AA4A6-33518F07@10.10.52.1 User-Agent: Cisco-SIPGateway/IOS-15.5.3.M4a Max-Forwards: 70 Timestamp: 1482850741 CSeq: 104 BYE Reason: Q.850;cause=16 P-RTP-Stat: PS=847,OS=135520,PR=534,OR=85440,PL=0,JI=0,LA=0,DU=17 Content-Length: 0 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x2529BEE0 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x2529BEE0 with refCount = 1 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x252DDB14 with refCount = 1 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [10.10.52.1]:61738, local_address:[10.10.52.1] Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x2529BEE0 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: BYE sip:900@10.10.52.1:5060 SIP/2.0 Via: SIP/2.0/UDP 10.10.52.1:5060;x-route-tag="tgrp:100";branch=z9hG4bK2921720 From: ;tag=1446A314-222D To: ;tag=1446A31C-15B5 Date: Tue, 27 Dec 2016 16:58:44 GMT Call-ID: CBDC4782-CB7B11E6-874AA4A6-33518F07@10.10.52.1 User-Agent: Cisco-SIPGateway/IOS-15.5.3.M4a Max-Forwards: 70 Timestamp: 1482850741 CSeq: 104 BYE Reason: Q.850;cause=16 P-RTP-Stat: PS=847,OS=135520,PR=534,OR=85440,PL=0,JI=0,LA=0,DU=17 Content-Length: 0 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/info/4096/sipSPICheckFromToRequest: Trying with child CCB 0x0 index 0 curr_child 0 Dec 27 16:59:01: //731/CBDA7271802A/SIP/Error/sipSPICheckFromToRequest: Failed FROM/TO Request check - IGNORE IF HAIRPIN CALL old_from: ;tag=1446A314-222D old_to: ;tag=1446A31C-15B5 new_from: ;tag=1446A314-222D new_to: ;tag=1446A31C-15B5 Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/verbose/4096/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x232D5578 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x252DDB14) counter, current msg->refCount = 2 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.10.52.1,Port 61738, Transport 1, SentBy Port 5060vrfid 0 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone EET to SIP default timezone = GMT Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.10.52.1,Port 61738, Transport 1, SentBy Port 5060vrfid 0 Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/verbose/4096/ccsip_set_release_source_for_peer: ownCallId[732], src[2] Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/info/4096/sipSPIStopHoldTimer: Stopping hold timer Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/verbose/4096/sipSPIUreasonHeader_to_ccCause: Cause=0 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/critical/4096/sipSPIGetContentGTD: No GTD found in inbound container Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/critical/4096/sipSPIInitiateDisconnect: Initiate call disconnect(16) for incoming call Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x252DB748) counter, current msg->refCount = 1 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/critical/4096/sipSPIGetContentQSIG: No QSIG Body found in inbound container Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/critical/4096/sipSPIGetContentQ931: No RawMsg Body found in inbound container Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/verbose/4096/ccsip_ipip_media_service_get_event_data: Event id = 33 Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/critical/32768/ccsip_ipip_media_forking_post_event: MF: Not a Anchor SIP leg.. Dec 27 16:59:01: //732/CBDA7271802A/SIP/State/sipSPIChangeState: 0x232D5578 : State change from (STATE_ACTIVE, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE) Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x252DB748 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x252DDB14) counter, current msg->refCount = 3 Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/verbose/4096/sipSPIAssignCcbLastRequest: Current ccb(0x232D5578)->last_request = 0x252DDB14, refCount = 3 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x252DDB14) counter, current msg->refCount = 2 Dec 27 16:59:01: //736/CFD8C7A98750/SIP/Info/verbose/8192/ccsip_call_statistics: Requesting stats for callid=736 Dec 27 16:59:01: //736/CFD8C7A98750/SIP/Info/critical/8192/ccsip_call_statistics: Stats request failed for callid=736, dstCallID=-1, rc=-7 Dec 27 16:59:01: //736/CFD8C7A98750/SIP/Info/verbose/4096/ccsip_ipip_media_service_get_event_data: Event id = 33 Dec 27 16:59:01: //736/CFD8C7A98750/SIP/Info/critical/32768/ccsip_ipip_media_forking_post_event: MF: Not a Anchor SIP leg.. Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISASSOCIATE Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/verbose/8192/ccsip_call_statistics: Requesting stats for callid=732 Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/critical/8192/ccsip_call_statistics: Stats request failed for callid=732, dstCallID=735, rc=-7 Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/verbose/4096/ccsip_ipip_media_service_get_event_data: Event id = 33 Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/critical/32768/ccsip_ipip_media_forking_post_event: MF: Not a Anchor SIP leg.. Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 8 Dec 27 16:59:01: //736/CFD8C7A98750/SIP/Info/info/133120/sipSPIBwCacReleaseDialPeerBw: bwcac dial-peer bw 80 Kbps released for tag 40002 active bw 0 Kbps Dec 27 16:59:01: //736/CFD8C7A98750/SIP/Info/info/131072/sipSPIBwCacReleaseInterfaceBw: bwcac releasing interface Loopback0 bw 80 Kbps Dec 27 16:59:01: //736/CFD8C7A98750/SIP/Info/info/131072/sipSPIBwCacReleaseAccountedBw: bwcac released accounted bw 80000 bps Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x252DB748 with refCount = 1 Dec 27 16:59:01: //736/CFD8C7A98750/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 3 event Dec 27 16:59:01: //736/CFD8C7A98750/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Dec 27 16:59:01: //736/CFD8C7A98750/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Dec 27 16:59:01: //736/CFD8C7A98750/SIP/Info/info/4096/sipSPISendCancel: Associated container=0x2362D6F0 to Cancel Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Dec 27 16:59:01: //736/CFD8C7A98750/SIP/Transport/sipSPISendCancel: Sending CANCEL to the transport layer Dec 27 16:59:01: //736/CFD8C7A98750/SIP/Transport/sipSPITransportSendMessage: msg=0x252DB748, addr=10.97.152.4, port=5060, sentBy_port=0, local_addr=10.10.52.1, is_req=1, transport=1, switch=0, callBack=0x35F259CC Dec 27 16:59:01: //736/CFD8C7A98750/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Dec 27 16:59:01: //736/CFD8C7A98750/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Dec 27 16:59:01: //736/CFD8C7A98750/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.97.152.4, rport:5060 with laddr:10.10.52.1 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: gcb=0x232DBC70 is already on connection=0x22600570 context_list Dec 27 16:59:01: //736/CFD8C7A98750/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x252DB748 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x252DB748, addr=10.97.152.4, port=5060, local_addr=10.10.52.1, connId=5 vrfid=0 for UDP Dec 27 16:59:01: //736/CFD8C7A98750/SIP/Info/info/512/sentCancelDisconnecting: Sent Cancel Request, starting CancelWaitResponseTimer Dec 27 16:59:01: //736/CFD8C7A98750/SIP/State/sipSPIChangeState: 0x232DBC70 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING) to (STATE_DISCONNECTING, SUBSTATE_NONE) Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 15 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 8 Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/info/133120/sipSPIBwCacReleaseDialPeerBw: bwcac dial-peer bw 80 Kbps released for tag 9000 active bw 0 Kbps Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/info/131072/sipSPIBwCacReleaseInterfaceBw: bwcac releasing interface Loopback0 bw 80 Kbps Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/info/131072/sipSPIBwCacReleaseAccountedBw: bwcac released accounted bw 80000 bps Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/info/4096/act_disconnecting_disconnect: Disconnect now.. no defer BYE.. Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x2529BEE0 with refCount = 1 Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 3 event Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/info/4096/sipSPISendByeResponse: Associated container=0x23630A80 to Bye Response Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Dec 27 16:59:01: //732/CBDA7271802A/SIP/Transport/sipSPISendByeResponse: Sending BYE Response to the transport layer Dec 27 16:59:01: //732/CBDA7271802A/SIP/Transport/sipSPITransportSendMessage: msg=0x2529BEE0, addr=10.10.52.1, port=61738, sentBy_port=5060, local_addr=10.10.52.1, is_req=0, transport=1, switch=0, callBack=0x35F25B54 Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Dec 27 16:59:01: //732/CBDA7271802A/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x225FF0A8, addr=10.10.52.1, port=5060, local_addr=10.10.52.1, unregistering context=0x232D5578 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x232D5578 from the connection=0x22600474 context list Dec 27 16:59:01: //732/CBDA7271802A/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x2529BEE0 to default port=5060 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.10.52.1, rport:5060 with laddr:10.10.52.1 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x232D5578 with connection=0x22600474 context list Dec 27 16:59:01: //732/CBDA7271802A/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x2529BEE0 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x2529BEE0, addr=10.10.52.1, port=5060, local_addr=10.10.52.1, connId=3 vrfid=0 for UDP Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/info/512/sentByeResponse: Sent 200ok to the BYE, tearing down the call Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/info/4096/sipSPISetCommonTimer: Started generic timer type 2 for 240000 millisecs Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/verbose/8192/sipSPIDeferCallClose: Not split dataplane, bail Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/verbose/8192/sipSPIWaitForStatsBforeCallClose: Not split dataplane, bail Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/verbose/4096/sipSPICallCloseAfterFinalStat: sipSPICallCloseAfterFinalStat: Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/info/12288/sipSPIIcpifUpdate: CallState: 4 Playout: 0 DiscTime:34019097 ConnTime 34017360 Dec 27 16:59:01: //732/CBDA7271802A/SIP/Media/sipSPIHandleDestroyRtpSession: stream:3E9583D8 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x252DDB14) counter, current msg->refCount = 1 Dec 27 16:59:01: //732/CBDA7271802A/SIP/State/sipSPIChangeState: 0x232D5578 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE) Dec 27 16:59:01: //732/CBDA7271802A/SIP/Call/sipSPICallInfo: The Call Setup Information is: Call Control Block (CCB) : 0x0x232D5578 State of The Call : STATE_DEAD TCP Sockets Used : NO Calling Number : 2109533545 Called Number : 900 Source IP Address (Sig ): 10.10.52.1 Destn SIP Req Addr:Port : 10.10.52.1:5060 Destn SIP Resp Addr:Port : 10.10.52.1:61738 Destination Name : 10.10.52.1 Dec 27 16:59:01: //732/CBDA7271802A/SIP/Call/sipSPIMediaCallInfo: Number of Media Streams: 1 Media Stream : 1 Negotiated Codec : g711alaw Negotiated Codec Bytes : 160 Nego. Codec payload : 8 (tx), 8 (rx) Negotiated Dtmf-relay : 8 Dtmf-relay Payload : 0 (tx), 0 (rx) Source IP Address (Media): 10.10.52.1 Source IP Port (Media): 17030 Destn IP Address (Media): 10.10.52.1 Destn IP Port (Media): 17028 Orig Destn IP Address:Port (Media): [ - ]:0 Dec 27 16:59:01: //732/CBDA7271802A/SIP/Call/sipSPICallInfo: Disconnect Cause (CC) : 16 Disconnect Cause (SIP) : 200 Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 2DC Dec 27 16:59:01: //732/CBDA7271802A/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Return and SIP_TIMER_REMOVE_TRANSACTION timer will free this ccb=0x232D5578 Dec 27 16:59:01: //736/CFD8C7A98750/SIP/Msg/ccsipDisplayMsg: Sent: CANCEL sip:501@10.97.152.4:5060 SIP/2.0 Via: SIP/2.0/UDP 10.10.52.1:5060;branch=z9hG4bK29177D From: ;tag=1446BD38-17F4 To: Date: Tue, 27 Dec 2016 16:58:50 GMT Call-ID: CFD96469-CB7B11E6-8753A4A6-33518F07@10.10.52.1 CSeq: 101 CANCEL Max-Forwards: 70 Timestamp: 1482850741 Reason: Q.850;cause=3 Content-Length: 0 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x252DB748 Dec 27 16:59:01: //732/CBDA7271802A/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.52.1:5060;x-route-tag="tgrp:100";branch=z9hG4bK2921720 From: ;tag=1446A314-222D To: ;tag=1446A31C-15B5 Date: Tue, 27 Dec 2016 16:59:01 GMT Call-ID: CBDC4782-CB7B11E6-874AA4A6-33518F07@10.10.52.1 Server: Cisco-SIPGateway/IOS-15.5.3.M4a Timestamp: 1482850741 CSeq: 104 BYE Reason: Q.850;cause=16 P-RTP-Stat: PS=534,OS=85440,PR=847,OR=135520,PL=0,JI=0,LA=0,DU=17 Content-Length: 0 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x2529BEE0 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x2529BEE0 with refCount = 1 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x252DB748 with refCount = 1 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [10.10.52.1]:61738, local_address:[10.10.52.1] Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x2529BEE0 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/info/1024/sipSPIMatchRespToReqTran: removing unneeded z9hG4bK2921720 from via branch list Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x252DB748) counter, current msg->refCount = 2 Dec 27 16:59:01: //731/CBDA7271802A/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.52.1:5060;x-route-tag="tgrp:100";branch=z9hG4bK2921720 From: ;tag=1446A314-222D To: ;tag=1446A31C-15B5 Date: Tue, 27 Dec 2016 16:59:01 GMT Call-ID: CBDC4782-CB7B11E6-874AA4A6-33518F07@10.10.52.1 Server: Cisco-SIPGateway/IOS-15.5.3.M4a Timestamp: 1482850741 CSeq: 104 BYE Reason: Q.850;cause=16 P-RTP-Stat: PS=534,OS=85440,PR=847,OR=135520,PL=0,JI=0,LA=0,DU=17 Content-Length: 0 Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/verbose/1024/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/sact_disconnecting_new_message_response: [sact_disconnecting_new_message_response] Received Response Class [2] Method Code [103] Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/info/4096/sipSPISetCommonTimer: Stopping timer type 2 to start 2 Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/info/4096/sipSPISetCommonTimer: Started generic timer type 2 for 240000 millisecs Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/verbose/8192/sipSPIDeferCallClose: Not split dataplane, bail Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/verbose/8192/sipSPIWaitForStatsBforeCallClose: Not split dataplane, bail Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/verbose/4096/sipSPICallCloseAfterFinalStat: sipSPICallCloseAfterFinalStat: Dec 27 16:59:01: //731/CBDA7271802A/SIP/Info/info/12288/sipSPIIcpifUpdate: CallState: 4 Playout: 8090 DiscTime:34019098 ConnTime 34017360 Dec 27 16:59:01: //731/CBDA7271802A/SIP/Media/sipSPIHandleDestroyRtpSession: stream:3AF92CFC Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3AFE1834 Dec 27 16:59:01: //731/CBDA7271802A/SIP/State/sipSPIChangeState: 0x232CEE80 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE)ACK sip:501@10.97.152.4:5060 SIP/2.0 Via: SIP/2.0/UDP 10.10.52.1:5060;branch=z9hG4bK29177D From: ;tag=1446BD38-17F4 To: ;tag=dccec1f18b67009cc1f16526-e2ef466b Date: Tue, 27 Dec 2016 16:58:50 GMT Call-ID: CFD96469-CB7B11E6-8753A4A6-33518F07@10.10.52.1 Max-Forwards: 70 CSeq: 101 ACK Allow-Events: kpml, telephone-event Content-Length: 0 Dec 27 16:59:01: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3AFE3184