vg-gib-001#ter mon vg-gib-001# Apr 9 10:10:42.343: ISDN Se0/1/0:15 Q931: RX <- SETUP pd = 8 callref = 0x0001 Sending Complete Bearer Capability i = 0x8090A3 Standard = CCITT Transfer Capability = Speech Transfer Mode = Circuit Transfer Rate = 64 kbit/s Channel ID i = 0xA98381 Exclusive, Channel 1 Progress Ind i = 0x8381 - Call not end-to-end ISDN, may have in-band info Progress Ind i = 0x8483 - Origination address is non-ISDN Calling Party Number i = 0x1183, '41797329888' Plan:ISDN, Type:International Called Party Number i = 0xC1, '02501' Plan:ISDN, Type:Subscriber(local) Apr 9 10:10:42.343: ISDN Se0/1/0:15 Q931: Received SETUP callref = 0x8001 callID = 0x020C switch = primary-net5 interface = User Apr 9 10:10:42.346: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x7FFDA8AFBAB8) with key=[567289] to table Apr 9 10:10:42.346: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init: Apr 9 10:10:42.346: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init: Apr 9 10:10:42.346: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised.. Apr 9 10:10:42.347: //-1/000000000000/SIP/Info/verbose/4097/ccsip_platform_init_ccb: Initialising rtp session queue Apr 9 10:10:42.347: //556180/000000000000/SIP/State/sipSPIChangeState: 0x7FFDA8AFBAB8 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/critical/32768/ccsip_ipip_media_forking_read_from_TDContainer: MF: Unable to read data from TD Container.. Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/critical/32768/ccsip_ipip_media_forking_forked_leg_config: MF: TD container cannot be read/container is NULL. Setting of forked call leg failed.. Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/verbose/4096/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 1, Event Id: EV_UNDEFINED Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/verbose/4096/ccsip_iwf_map_ccapi_event_to_iwf_event: IWF Event: E_SIP_IWF_EV_SET_MODE Apr 9 10:10:42.347: //556180/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_default_early_dialog_container, cur_state:S_SIP_IWF_SDP_IDLE, event:E_SIP_IWF_EV_SET_MODE Apr 9 10:10:42.347: //556180/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/is_mode_sip_sip_md_snr: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/is_mode_sip_sip_ed_snr: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/is_mode_sip_sip_md: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/is_mode_sip_sip_ed: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/is_mode_sip_h32x_in_set_mode: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/is_mode_sip_h323_in_set_mode: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/is_mode_sip_sccp_in_set_mode: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/is_mode_sip_sccp_in_set_mode: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/8192/sip_iwf_def_set_mode_hdlr: Setting SPI mode to SIP-TDM Apr 9 10:10:42.347: //556180/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_default_early_dialog_container Apr 9 10:10:42.347: //556180/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:CNFSM_NO_STATE_CHANGE Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/ccsip_iwf_handle_peer_event: Return value: SIP_IWF_SUCCESS Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/verbose/4096/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 3, Event Id: CC_EV_IF_DIAG_DONE Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/verbose/4096/ccsip_iwf_map_ccapi_event_to_iwf_event: IWF Event: E_SIP_IWF_EV_SET_FLOW_MODE Apr 9 10:10:42.347: //556180/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_default_early_dialog_container, cur_state:S_SIP_IWF_SDP_IDLE, event:E_SIP_IWF_EV_SET_FLOW_MODE Apr 9 10:10:42.347: //556180/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/is_fa2ft_md_flow_mode_transition: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/is_fa2ft_flow_mode_transition: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/ccsip_get_flow_mode_frm_set_flow_mode_ev: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/is_fa2ft_flow_mode_transition: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/ccsip_get_flow_mode_frm_set_flow_mode_ev: Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/verbose/4096/ccsip_iwf_process_event: IWF - cnfsm ret 2 Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/ccsip_iwf_handle_peer_event: Return value: SIP_IWF_SUCCESS Apr 9 10:10:42.347: //556180/000000000000/SIP/Info/info/4096/ccsip_call_setup_request: Before processing SETUP REQccb->pld.flags_ipip = 200 Apr 9 10:10:42.348: //556180/000000000000/SIP/Info/info/4096/ccsip_call_setup_request: After processing SETUP REQccb->pld.flags_ipip = 200 Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/verbose/4096/ccsip_call_setup_request: Number Translation Set For Called-Number Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Error/sipSPIGetCallSessionTarget: No session target configured Apr 9 10:10:42.348: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIProcessTargetInfoDestList: Processing target destination list Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable: Adding call id 87C94 to table Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/notify/131072/ccsip_call_setup_request: Incrementing call counter to [1] in dial-peer [500] Apr 9 10:10:42.348: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_SETUP Apr 9 10:10:42.348: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 2 Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/info/2049/sipSPIGetCallConfig: preferred_codec set[0] type :No Codec bytes: 0 Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/verbose/2048/sipSPI_ipip_store_config_info: Setting mid_call_config_info = 0x0 for callid = 556180 Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/info/8192/sipSPIGetCallConfig: Media forking disabled Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/info/32768/sipSPIGetCallConfig: Media Antitrombone disabled Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/notify/131072/sipSPICanSetFallbackFlag: Local Fallback is not active Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/info/8192/sipSPIGetCallConfig: VRF id = 0 Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/info/8192/sipSPISetMediaFlowMode: Storing the configured mode as FLOW-THROUGH Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/info/2304/sipSPISetMediaFlowMode: xcoder high-density disabled Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/info/8192/sipSPISetMediaFlowMode: Flow Mode set to FLOW_THROUGH Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/info/1/sipSPIGetCallConfig: Using Voice Class Codec, tag = 10 and offer-all is = FALSE Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Media/sipSPICopyStunConfigFromPeerToCCB: Firewall traversal is not enabled Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/verbose/12288/sipSPIGetModemInfoPerCall: peer_callID=556179 Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/info/8192/sipSPIGetModemConfig: From Config: Modem NSE payload = 100, Passthrough = 4, Modem relay = 0, Gw-Xid = 1 SPRT latency 200, SPRT Retries = 12, Dict Size = 1024 String Len = 32, Compress dir = 3 Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/critical/32768/ccsip_ipip_media_forking_update_preferred_codec: MF: Not a Forked SIP leg.. Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/info/8704/sipSPIGetCallConfig: Incoming: No defer BYE for last call stats Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/verbose/1/ccsip_set_srtp_config: No Srtp configure for this leg. Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/info/8192/sipSPIGetCallConfig: Media forking disabled Apr 9 10:10:42.348: //556180/54CD023D81DA/SIP/Info/info/34816/ccsip_ipip_media_forking_anchor_leg_config: MF: en_p->encap_s.voIP.voipPeerCfgMediaClass = 0 Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/info/34816/ccsip_ipip_media_forking_anchor_leg_config: MF: Dial-peer has no media class recorder. Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/info/36864/sipSPIMFChangeState: MF: Prev state = 0 & New state = -1 Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/info/32768/ccsip_ipip_media_forking_anchor_leg_reset: MF: Anchor leg config reset done... Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/info/32768/ccsip_ipip_media_forking_intra_frame_request_config: MF: FIR en_p->encap_s.voIP.voipPeerCfgMediaClass = 0 Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/info/32768/ccsip_ipip_media_forking_get_forked_leg_config: MF: This leg is not forked call leg. Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/critical/11264/ccsipInitDSCPPolicyInfo: No DSCP Profile configured, No RPH 2 DSCP Mapping and DSCP policing Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/verbose/8192/sipSPIGetCallConfig: Initilise the DSCP policy Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/verbose/8192/sipSPICheckFAAnatAssymetricOrDO2EO: Not a SIP-SIP call or not in FA mode Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/notify/2049/populate_vcc_data: Using Voice Class Codec, tag = 10 and offer-all is = FALSE Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/notify/8192/sipSPISetOverlapConfiguration: Overlap signaling: FALSE: Endpt: SIP Trunk Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/verbose/10240/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0 Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/verbose/2048/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0 Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/notify/10240/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/info/1/preprocessSetup: This is a not a SIGO Call -, could be DM call Apr 9 10:10:42.349: //556180/54CD023D81DA/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_INIT_CALL_SETUP Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/verbose/4096/ccsip_iwf_process_event: IWF - cnfsm ret 2 Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/notify/4096/preprocessSetup: SIP-TDM or TCL/VXML app case Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/notify/6/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/verbose/513/resolve_media_ip_address_to_bind: peer_tag=500 Apr 9 10:10:42.349: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_media_ip_address_to_bind: VRF id = 0 Apr 9 10:10:42.349: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.50.66.1 for SIP Apr 9 10:10:42.349: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.50.66.1 for SIP Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.50.66.1 Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/critical/1/sipSPIOutgoingCallSDP: Failure in creating outbound streams SIP: (556180) Group (a= group line) attribute, level 65535 instance 1 not found. Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Apr 9 10:10:42.349: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.50.66.1 for SIP Apr 9 10:10:42.349: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.50.66.1 for SIP Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 10.50.66.1 Apr 9 10:10:42.349: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 10.50.66.1 Apr 9 10:10:42.349: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIReserveRtpPort: reserved port 20240 for stream 1 Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Info/info/1/sipSPIDoBearerCapToCodecMapping: Bearer capability to Codec Mapping: DISABLED Apr 9 10:10:42.349: //556180/54CD023D81DA/SIP/Media/sipSPIAddSDPMediaPayload: Preferred method of dtmf relay is: 6, with payload: 101 Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/info/131074/sipSPIBwCacCalcMaxAudioBandwidth: calculating max bw from preffered codecs (local offer) SIP: (556180) Group (a= group line) attribute, level 65535 instance 1 not found. Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/info/131074/sipSPIBwCacCalcMaxAudioBandwidth: max bw (excluding pak overhead) from preffered codecs: codec g711ulaw bw 64000 index 0 Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/critical/2/sipSPIBwCacCalcMaxAudioBandwidth: audio caps channel idx not found !!!! Apr 9 10:10:42.350: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20 Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/info/131074/sipSPIBwCacCalcMaxAudioBandwidth: max bw (including pak overhead) from preffered codecs: codec g711ulaw bw 80000 Apr 9 10:10:42.350: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20 Apr 9 10:10:42.350: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/convert_codec_bytes_to_ptime: Values :Codec: g711alaw codecbytes :160, ptime: 20 Apr 9 10:10:42.350: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/convert_codec_bytes_to_ptime: Values :Codec: g729r8 codecbytes :20, ptime: 20 Apr 9 10:10:42.350: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/sipSPISetMediaDirectionForStream: Setting Media direction SENDRECV for stream 1 Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/notify/8193/sip_generate_sdp_xcaps_list: Modem Relay and T38 disabled. X-cap not needed Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/info/1/sipSPIOutgoingCallSDP: Creating recv-only stream for outbound call Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Media/sipSPIProcessRtpSessions: Processing stream state = STREAM_IDLE Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Media/sipSPIProcessRtpSessions: No active streams. Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/notify/4096/sip_gw_pre_setup_update_stream_media_direction: peer_callID = 556179 Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/critical/4097/sip_gw_pre_setup_update_stream_media_direction: peer_channels/stream is NULL Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/verbose/1/sip_gw_pre_setup_add_sdp_container: SDP container added Apr 9 10:10:42.350: //556180/54CD023D81DA/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 Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/info/131072/sipSPIBwCacUpdateInterfaceBw: bwcac acquiring interface Loopback0 bw 80 Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/info/131072/sipSPIBwCacUpdateAccountedBw: bwcac update accounted bw (initial offer) accounted bw set to 80000 Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/info/133120/sipSPIBwCacIsDialPeerBwAvailable: bwcac NOP dial-peer bw available tag 500 Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/notify/1/sipSPIBwCacIsInterfaceBwAvailable: bwcac interface bw threshold not configured Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/info/131072/sipSPIBwCacVerifyBwThreshold: bwcac verify bw threshold, bw available allow call total bw 80000 bps Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/critical/8192/sipSPIValidateGtd: Signal Forward disabled Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/critical/8192/sipSPIValidateTunnelData: RawMsg/QSIG Tunneling Not Enabled Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/critical/10240/sipSPIAddMLPPServicesInfo: No MLP Info available on incoming leg Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/info/3072/sipSPIPreprocessUriFormat: Url cfg for 1: 2,phone-ctxt=FALSE Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/info/9216/sipSPIAddCiscoGcid: Gcid value not set - not adding header. Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/verbose/8192/sipSPIAddPrivacyandIdentityInfo: Removing "id" value from Privacy Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/critical/2048/sipSPICompareHistoryInfoWithMatchedDialpeer: call-route history-info CLI not enabled Apr 9 10:10:42.350: //556180/54CD023D81DA/SIP/Info/critical/1024/sipSPI_ipip_set_history_info_header: No HI header recvd from container Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Apr 9 10:10:42.351: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.50.66.1 for SIP Apr 9 10:10:42.351: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.50.66.1 for SIP Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 10.50.66.1 Apr 9 10:10:42.351: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 10.50.66.1 Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/Info/info/131072/sipSPIRscmsmAvail: Value returned by check is = 0 Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Apr 9 10:10:42.351: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.50.66.1 for SIP Apr 9 10:10:42.351: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.50.66.1 for SIP Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 10.50.66.1 Apr 9 10:10:42.351: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 10.50.66.1 Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/Info/verbose/4096/sipSPIUaddCcbToUACTable: ****Adding to UAC table.0x7FFDA8AFBAB8 54CE3B25-3B0411E8-93DEAD25-DD7BDD2E@10.50.66.1 Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x7FFDA8AFBAB8 key=54CE3B25-3B0411E8-93DEAD25-DD7BDD2E@10.50.66.1 balance 1 Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/Info/verbose/12288/sipSPIUsetBillingProfile: sipCallId for billing records = 54CE3B25-3B0411E8-93DEAD25-DD7BDD2E@10.50.66.1 Apr 9 10:10:42.351: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.1.128.135,Port 5060, Transport 2, SentBy Port 5060vrfid 0 Apr 9 10:10:42.351: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone MEZ_SZ to SIP default timezone = GMT Apr 9 10:10:42.351: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFD9D9341A0 with refCount = 1 Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_REQ Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/Event/Session-Timer/sipSTSLMain: dir:1, method:102, resp_code:0, container:7FFDB33289A0 Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/Info/info/8192/Session-Timer/sipSTSLSRReqSend: Session timer is not required Apr 9 10:10:42.351: //556180/54CD023D81DA/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 Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 0 event Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/Info/info/4096/ccsip_offer_ans_handle_sent_sdp: Apr 9 10:10:42.351: //556180/54CD023D81DA/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_SENT Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/Info/info/4096/ccsip_offer_ans_is_invite_offer_valid: TRUE Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/Info/info/4096/ccsip_offer_ans_common_offer_sent_hdlr: Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/Info/info/4096/ccsip_iwf_handle_network_event: Apr 9 10:10:42.351: //556180/54CD023D81DA/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_SENT_SDP Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/Info/info/4096/sip_iwf_def_ed_sent_sdp_offer_hdlr: Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:S_SIP_IWF_SDP_SENT_AWAIT_SDP Apr 9 10:10:42.351: //556180/54CD023D81DA/SIP/State/ccsip_cnfsm_debugs: OA:next_state:S_SIP_EARLY_DIALOG_OFFER_SENT Apr 9 10:10:42.352: //-1/xxxxxxxxxxxx/SIP/Info/info/2048/sipSPIgetRegistrarHost: registrar host retrieved : 10.50.66.1 Apr 9 10:10:42.352: //556180/54CD023D81DA/SIP/Info/critical/4096/ccsip_ipip_media_forking_get_forked_recording_data: MF: Not a Forked leg.. Apr 9 10:10:42.352: //556180/54CD023D81DA/SIP/Info/critical/1024/sipSPICreateRecParticipantHeaders: X-Cisco-Recording-Participant header not added. SIP: (556180) Group (a= group line) attribute, level 65535 instance 1 not found. Apr 9 10:10:42.352: //556180/54CD023D81DA/SIP/Info/info/34816/sipSPIGetCallExtensionSupported: anat enabled, src_sdp dont have anat Apr 9 10:10:42.352: //556180/54CD023D81DA/SIP/Info/info/4096/sipSPISendInvite: Associated container=0x7FFDB33289A0 to Invite Apr 9 10:10:42.352: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 361 Apr 9 10:10:42.352: //556180/54CD023D81DA/SIP/Transport/sipSPISendInvite: Sending Invite to the transport layer Apr 9 10:10:42.352: //556180/54CD023D81DA/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Dial peer configuration, Switch Transport is FALSE Apr 9 10:10:42.352: //556180/54CD023D81DA/SIP/Transport/sipSPITransportSendMessage: msg=0x7FFD9D9341A0, addr=10.1.128.135, port=5060, sentBy_port=0, local_addr=10.50.66.1, is_req=1, transport=2, switch=0, callBack=0x7FFE0B235750 Apr 9 10:10:42.352: //556180/54CD023D81DA/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:10:42.352: //556180/54CD023D81DA/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:10:42.352: //556180/54CD023D81DA/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 9 10:10:42.352: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.1.128.135, rport:5060 with laddr:10.50.66.1 Apr 9 10:10:42.352: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x7FFDA8AFBAB8 with connection=0x7FFDA0F7BF18 context list Apr 9 10:10:42.352: //556180/54CD023D81DA/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x7FFD9D9341A0 Apr 9 10:10:42.352: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x7FFD9D9341A0, addr=10.1.128.135, port=5060, local_addr=10.50.66.1, connId=65 vrfid=0 for TCP Apr 9 10:10:42.352: //556180/54CD023D81DA/SIP/Info/info/512/sentInviteRequest: Sent Invite in state STATE_IDLE Apr 9 10:10:42.352: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sentInviteRequest: Transaction active. Facilities will be queued. Apr 9 10:10:42.352: //556180/54CD023D81DA/SIP/State/sipSPIChangeState: 0x7FFDA8AFBAB8 : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_SENT_INVITE, SUBSTATE_NONE) Apr 9 10:10:42.352: //556180/54CD023D81DA/SIP/Media/sipSPIProcessRtpSessions: Processing stream state = STREAM_ADDING Apr 9 10:10:42.352: //556180/54CD023D81DA/SIP/Info/verbose/6/sipSPIAddStream: set stream_callid from ccb->ccCallID:0x87C94, media_type:0 Apr 9 10:10:42.352: //556180/54CD023D81DA/SIP/Media/sipSPIAddStream: Adding stream 1 of type voice+dtmf (callid 556180) to the VOIP RTP library Apr 9 10:10:42.352: //556180/54CD023D81DA/SIP/Info/notify/6/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Apr 9 10:10:42.352: //556180/54CD023D81DA/SIP/Info/verbose/513/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr Apr 9 10:10:42.352: //556180/54CD023D81DA/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.50.66.1 Apr 9 10:10:42.352: //556180/54CD023D81DA/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1 Apr 9 10:10:42.353: //556180/54CD023D81DA/SIP/Info/info/1/sipSPIAssignStreamCallId: Assigning streamid 556180 to stream 1. Old streamid = 556180 Apr 9 10:10:42.353: //556180/54CD023D81DA/SIP/Info/info/8192/sipSPIUpdateRtcpSession: ccb->flags != LOOPBACK Apr 9 10:10:42.353: //556180/54CD023D81DA/SIP/Media/sipSPIUpdateRtcpSession: Setting do_rtcp = FALSE 0 Apr 9 10:10:42.353: //556180/54CD023D81DA/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info laddr = 10.50.66.1, lport = 20240, raddr = 0.0.0.0, rport=0, do_rtcp=FALSE src_callid = 556180, dest_callid = -1, stream type = voice+dtmf, stream direction = SENDRECV media_ip_addr = - , vrf tableid = 0 media_addr_type = 1 negotiated_bandwidth (kbps) = 0 srtp_services = 0 nat_flag = 0 Apr 9 10:10:42.353: //556180/54CD023D81DA/SIP/Media/sipSPIUpdateRtcpSession: No rtp session, creating a new one Apr 9 10:10:42.353: //556180/54CD023D81DA/SIP/Info/verbose/1/sipSPICreateRtpSession: sess: 7FFDB3208BF8 do_rtcp:0 Apr 9 10:10:42.353: //556180/54CD023D81DA/SIP/Media/sipSPICreateRtpSession: stun is disabled Apr 9 10:10:42.353: //556180/54CD023D81DA/SIP/Info/critical/131072/sipSPIUpdateRtcpSession: Not able to Associate DSCP Profile with GCCB dscp_policy = 0x0, IS_SIPSPI_MODE_IN_SIP_SIP = 0 dscpPolicySeviceBlock = 0x0 , stream->qos_info = 0x0 Apr 9 10:10:42.353: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIUpdateRtcpSession: Voice quality monitoring is not enabled for this RTP session due to sdp passthru enabled Apr 9 10:10:42.353: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIUpdateRtcpSession: VQM: gccb=0x0, gccb->callId=0, ccb->ccCallID=556180 Apr 9 10:10:42.353: //556180/54CD023D81DA/SIP/Info/notify/2080/sipSPIUpdateRtcpSession: DTMF inb/oob disabled Apr 9 10:10:42.353: //556180/54CD023D81DA/SIP/State/sipSPIChangeStreamState: Stream (callid = 556180) State changed from (STREAM_ADDING) to (STREAM_ACTIVE) Apr 9 10:10:42.353: //556180/54CD023D81DA/SIP/Info/info/2/sipSPIUpdateCallEntry: Call 556180 set InfoType to SPEECH Apr 9 10:10:42.353: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_tcp_queue_event: Event type: send msg, connid: 65, fd: 7 Apr 9 10:10:42.353: //556180/54CD023D81DA/SIP/Msg/ccsipDisplayMsg: Sent: INVITE sip:+35020002501@10.1.128.135 SIP/2.0 Via: SIP/2.0/TCP 10.50.66.1:5060;branch=z9hG4bK56C7A146A From: ;tag=7AA1D189-2377 To: Date: Mon, 09 Apr 2018 08:10:42 GMT Call-ID: 54CE3B25-3B0411E8-93DEAD25-DD7BDD2E@10.50.66.1 Supported: 100rel,timer,resource-priority,replaces,sdp-anat Min-SE: 1800 Cisco-Guid: 1422721597-0990122472-2178599958-2120343360 User-Agent: Cisco-SIPGateway/IOS-15.4.3.S4 Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER CSeq: 101 INVITE Max-Forwards: 70 Timestamp: 1523261442 Contact: Call-Info: ;method="NOTIFY;Event=telephone-event;Duration=2000" Expires: 180 Allow-Events: telephone-event Content-Type: application/sdp Content-Disposition: session;handling=required Content-Length: 361 v=0 o=CiscoSystemsSIP-GW-UserAgent 6628 2030 IN IP4 10.50.66.1 s=SIP Call c=IN IP4 10.50.66.1 t=0 0 m=audio 20240 RTP/AVP 0 8 18 100 101 c=IN IP4 10.50.66.1 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:100 X-NSE/8000 a=fmtp:100 192-194 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 Apr 9 10:10:42.354: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFD9D9341A0 Apr 9 10:10:42.354: ISDN Se0/1/0:15 Q931: TX -> CALL_PROC pd = 8 callref = 0x8001 Channel ID i = 0xA98381 Exclusive, Channel 1 Apr 9 10:10:42.410: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 7 to index 65 Apr 9 10:10:42.410: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFD9D9341A0 with refCount = 1 Apr 9 10:10:42.410: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB3098A28 with refCount = 1 Apr 9 10:10:42.410: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFD9D9341A0 Apr 9 10:10:42.410: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Apr 9 10:10:42.410: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x7FFDA0BDA5E8ACK sip:+35020002501@10.1.128.135:5060;transport=tcp SIP/2.0 Via: SIP/2.0/TCP 10.50.66.1:5060;branch=z9hG4bK56C7B1203 From: ;tag=7AA1D189-2377 To: ;tag=20448815~066d7f19-322a-43ba-8eca-ef58947b04ca-62721385 Date: Mon, 09 Apr 2018 08:10:42 GMT Call-ID: 54CE3B25-3B0411E8-93DEAD25-DD7BDD2E@10.50.66.1 Max-Forwards: 70 CSeq: 101 ACK Allow-Events: telephone-event Content-Length: 0 Apr 9 10:10:42.489: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB3098A28 Apr 9 10:10:42.576: ISDN Se0/1/0:15 Q931: RX <- CONNECT_ACK pd = 8 callref = 0x0001 Apr 9 10:10:45.445: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 2 to index 63 Apr 9 10:10:45.445: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB3339018 with refCount = 1 Apr 9 10:10:45.445: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB3098A28 with refCount = 1 Apr 9 10:10:45.445: //-1/xxxxxxxxxxxx/SIP/Info/critical/1024/httpish_msg_process_network_msg: HEADER LINE READ FAILURE DUE TO RS->EOF Apr 9 10:10:45.445: //-1/xxxxxxxxxxxx/SIP/Info/critical/1024/ccsip_process_network_message: process_network_msg: not complete Apr 9 10:10:45.445: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB3098A28 Apr 9 10:10:45.445: //-1/xxxxxxxxxxxx/SIP/Info/critical/4096/sip_tcp_newmsg_to_spi: process_network_msg: not complete Apr 9 10:10:45.445: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB3339018 Apr 9 10:10:45.446: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 2 to index 63 Apr 9 10:10:45.446: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB3339018 with refCount = 1 Apr 9 10:10:45.446: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFD9D9341A0 with refCount = 1 Apr 9 10:10:45.447: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB3339018 Apr 9 10:10:45.447: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Apr 9 10:10:45.447: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Apr 9 10:10:45.447: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x7FFDA0BDA5E8, addr=10.1.128.135, port=54378, local_addr=10.50.66.1, connid=63, transport=TCP Apr 9 10:10:45.447: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 54378 connId 63 Apr 9 10:10:45.447: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: INVITE sip:+41797329888@10.50.66.1:5060;transport=tcp SIP/2.0 Via: SIP/2.0/TCP 10.1.128.135:5060;branch=z9hG4bK8f4211138ed32d From: ;tag=20448815~066d7f19-322a-43ba-8eca-ef58947b04ca-62721385 To: ;tag=7AA1D189-2377 Date: Mon, 09 Apr 2018 08:10:45 GMT Call-ID: 54CE3B25-3B0411E8-93DEAD25-DD7BDD2E@10.50.66.1 Supported: timer,resource-priority,replaces Cisco-Guid: 1422721597-0990122472-2178599958-2120343360 User-Agent: Cisco-CUCM10.5 Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY CSeq: 101 INVITE Max-Forwards: 70 Expires: 180 Allow-Events: presence Call-Info: ;x-cisco-video-traffic-class=MIXED Supported: X-cisco-srtp-fallback Supported: Geolocation Session-Expires: 14400;refresher=uac Min-SE: 1800 P-Preferred-Identity: Remote-Party-ID: ;party=calling;screen=no;privacy=off Contact: Content-Type: application/sdp Content-Length: 363 v=0 o=CiscoSystemsCCM-SIP 20448815 2 IN IP4 10.1.128.135 s=SIP Call c=IN IP4 10.1.100.45 t=0 0 m=image 56340 udptl t38 a=T38FaxVersion:3 a=T38MaxBitRate:9600 a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxTranscodingJBIG:0 a=T38FaxRateManagement:transferredTCF a=T38FaxUdpEC:t38UDPRedundancy a=T38FaxMaxBuffer:200 a=T38FaxMaxDatagram:72 Apr 9 10:10:45.447: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Apr 9 10:10:45.447: //556180/54CD023D81DA/SIP/Info/info/4096/sipSPICheckFromToRequest: Found matching CB 7FFDA8AFBAB8 Apr 9 10:10:45.447: //556180/54CD023D81DA/SIP/Info/info/4096/sipSPILocateInviteDialogCCB: ****Found CCB in UAC table Apr 9 10:10:45.447: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x7FFD9D9341A0) counter, current msg->refCount = 2 Apr 9 10:10:45.447: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.1.128.135,Port 54378, Transport 2, SentBy Port 5060vrfid 0 Apr 9 10:10:45.447: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone MEZ_SZ to SIP default timezone = GMT Apr 9 10:10:45.447: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.1.128.135,Port 54378, Transport 2, SentBy Port 5060vrfid 0 Apr 9 10:10:45.447: //556180/54CD023D81DA/SIP/Info/info/4096/sact_active_new_message_request: Case of Mid-Call INVITE/UPDATE in ACTIVE STATE Apr 9 10:10:45.447: //556180/54CD023D81DA/SIP/Info/info/4096/sipSPISetCallingInfo: calling host comes from From: 10.1.128.135 Apr 9 10:10:45.447: //-1/xxxxxxxxxxxx/SIP/Error/httpish_msg_free: Freeing NULL pointer! Apr 9 10:10:45.448: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x7FFD9D9341A0) counter, current msg->refCount = 3 Apr 9 10:10:45.448: //556180/54CD023D81DA/SIP/Info/verbose/4096/sipSPIAssignCcbLastRequest: Current ccb(0x7FFDA8AFBAB8)->last_request = 0x7FFD9D9341A0, refCount = 3 Apr 9 10:10:45.448: //-1/xxxxxxxxxxxx/SIP/Info/critical/4096/sipSPIGetContentGTD: No GTD found in inbound container Apr 9 10:10:45.448: //556180/54CD023D81DA/SIP/Info/info/4096/ccsip_api_request_offer: Setting passthru/copylist event to 14 Apr 9 10:10:45.448: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB2D061F8 Apr 9 10:10:45.448: //556180/54CD023D81DA/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_REQ Apr 9 10:10:45.448: //556180/54CD023D81DA/SIP/Event/Session-Timer/sipSTSLMain: dir:2, method:102, resp_code:0, container:7FFDB3329B18 Apr 9 10:10:45.448: //556180/54CD023D81DA/SIP/Info/info/8192/Session-Timer/sipSTSLExtractSessionExpiresHdr: Session-Expires value: 14400 refresher: uac Apr 9 10:10:45.448: //556180/54CD023D81DA/SIP/Info/info/8192/Session-Timer/sipSTSLExtractMinSEHdr: Min-SE Duration: 1800 Apr 9 10:10:45.448: //556180/54CD023D81DA/SIP/Info/info/8192/Session-Timer/sipSTSLMain: SE: 14400;refresher:uac peer refresher:none, flags:2001, posted event:E_STSL_INVALID_PEER_EVENT, reason:4 Configured SE:1800, Configured Min-SE:1800 Apr 9 10:10:45.448: //556180/54CD023D81DA/SIP/Info/notify/10240/ccsip_api_request_offer: Incoming/Outgoing updates for callerid is globally disabled Apr 9 10:10:45.448: //556180/54CD023D81DA/SIP/Info/verbose/2048/ccsip_api_request_offer: ccb->pld.flags_ipip:0x201; invoke sipSPI_ipip_save_sdp_context Apr 9 10:10:45.448: //556180/54CD023D81DA/SIP/Info/notify/13312/sipSPIProcessNotifyCallInfoHeader: Call-Info header with for Unsolicited Notify Absent,Disabling Unsolicited Notifies Apr 9 10:10:45.448: //556180/54CD023D81DA/SIP/Info/verbose/1/sipSPIDoMediaNegotiation: Number of m-lines = 1 Apr 9 10:10:45.448: //556180/54CD023D81DA/SIP/Info/verbose/1/sipSPIValidateConnectionAddress: Dest port = 56340 SIP: Attribute mid, level 1 instance 1 not found. Apr 9 10:10:45.448: //556180/54CD023D81DA/SIP/Info/notify/6/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Apr 9 10:10:45.448: //556180/54CD023D81DA/SIP/Info/verbose/513/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr Apr 9 10:10:45.448: //556180/54CD023D81DA/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.50.66.1 Apr 9 10:10:45.448: //556180/54CD023D81DA/SIP/Media/sipSPIDoFaxAttributeNegotiation: remote bit rate: 9600, our bit rate: 14400 Apr 9 10:10:45.448: //556180/54CD023D81DA/SIP/Media/sipSPIDoFaxAttributeNegotiation: used bit rate: 9600 Apr 9 10:10:45.448: //556180/54CD023D81DA/SIP/Info/notify/8/sipSPIDoFaxMediaNegotiation: T.38 negotiated Apr 9 10:10:45.448: //556180/54CD023D81DA/SIP/State/sipSPIChangeStreamState: Stream (callid = -1) State changed from (STREAM_DEAD) to (STREAM_ADDING) Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Media/sipSPICompareStreams: stream 1 dest_port: old=56340 new=56340 Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Media/sipSPIGetNewLocalMediaDirection: New Remote Media Direction = SENDRECV Present Local Media Direction = SENDRECV New Local Media Direction = SENDRECV retVal = 0 Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Media/sipSPICompareMediaType: Media type switching from 0 to 11 for stream 1 Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/State/sipSPIChangeStreamState: Stream (callid = -1) State changed from (STREAM_ACTIVE) to (STREAM_CHANGING) Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Media/sipSPICompareStreams: negotiated codec changed from g711ulaw to T38Fax Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Media/sipSPICompareStreams: Flags set for stream 1: RTP_CHANGE=Yes CAPS_CHANGE=Yes RSVP_ADDR_CHANGE=No RSVP_MEDIA_CHANGE=Yes Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Media/sipSPICompareSDP: Flags set for call: NEW_MEDIA=Yes DSPDNLD_REQD=Yes IPIP_MEDIA=Yes Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Media/sipSPIRSVPCompareSDP: Media Type Change Identified Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Media/sipSPIRSVPCompareSDP: Media Codec Change Identified Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Info/verbose/1/ccsip_api_request_offer: Media Changes : 24: Codec_change Type_change Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Info/info/131073/sipSPIDoQoSNegotiationWithMediaLine: QOS negotiation for mline_index 1 Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Info/notify/131072/sipSPIDoStreamQoSNegotiation: Best effort Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Info/verbose/1/ccsip_api_request_offer: update SrcSdpVariablePart and MediaDirectionForAllStreams, Send Answer Locally Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Error/sipIPIP_add_bandwidth_line: Unknown media_type = 11 Apr 9 10:10:45.449: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/sipSPISetMediaDirectionForStream: Setting Media direction SENDRECV for stream 1 Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Info/info/1/sipSPIUpdateSrcSdpVariablePart: Setting stream 1 portnum to 20240 Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Info/notify/1/sipSPIUpdateSrcSdpVariablePart: SIP update src sdp, negoitated codec 17, payload type 255 Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Info/notify/1/sipSPIUpdateMediaDirectionForAllStreams: update media direction Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Info/verbose/4097/sipSPI_ipip_is_escalation: local channels = 0, peer channels = 0 Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Media/sipSPIGetNewLocalMediaDirection: New Remote Media Direction = SENDRECV Present Local Media Direction = SENDRECV New Local Media Direction = SENDRECV retVal = 0 Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Info/info/1/is_call_held: Remote media IP addr: 10.1.100.45 Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Info/info/1/is_call_held: Media IP Addr 10.1.100.45, RTCP Type 3 Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Info/verbose/1/sipSPIProcessMediaChanges: sipSPIProcessMediaChanges Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Media/sipSPIProcessRtpSessions: Processing stream state = STREAM_CHANGING Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Media/sipSPIProcessStreamChanging: flags_ipip_media:0x10800, is_main:1, NumStream:1, Num VideoStreams:0 Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Info/info/1/sipSPIAssignStreamCallId: Assigning streamid 556180 to stream 1. Old streamid = -1 Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Info/notify/6/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Info/verbose/513/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.50.66.1 Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Media/sipSPIHandleDestroyRtpSession: stream:7FFDB2049D90 Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Media/sipSPIModifyStream: modify a stream without SDP passthru Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Info/verbose/4097/sipSPI_ipip_is_escalation: local channels = 0, peer channels = 0 Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Media/sipSPIGetNewLocalMediaDirection: New Remote Media Direction = SENDRECV Present Local Media Direction = SENDRECV New Local Media Direction = SENDRECV retVal = 0 Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1 Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Info/info/1/sipSPIAssignStreamCallId: Assigning streamid 556180 to stream 1. Old streamid = 556180 Apr 9 10:10:45.449: //556180/54CD023D81DA/SIP/Info/info/8192/sipSPIUpdateRtcpSession: ccb->flags != LOOPBACK Apr 9 10:10:45.450: //556180/54CD023D81DA/SIP/Media/sipSPIUpdateRtcpSession: Setting do_rtcp = FALSE 0 Apr 9 10:10:45.450: //556180/54CD023D81DA/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info laddr = 10.50.66.1, lport = 20240, raddr = 10.1.100.45, rport=56340, do_rtcp=FALSE src_callid = 556180, dest_callid = 556179, stream type = voice+dtmf, stream direction = SENDRECV media_ip_addr = 10.1.100.45, vrf tableid = 0 media_addr_type = 1 negotiated_bandwidth (kbps) = 0 srtp_services = 0 nat_flag = 0 Apr 9 10:10:45.450: //556180/54CD023D81DA/SIP/Media/sipSPIUpdateRtcpSession: RTP session already created - update Apr 9 10:10:45.450: //556180/54CD023D81DA/SIP/Media/sipSPIUpdateRtpSession: stun is disabled for stream:7FFDB2049D90 Apr 9 10:10:45.450: //556180/54CD023D81DA/SIP/Info/critical/131072/sipSPIUpdateRtcpSession: Not able to Associate DSCP Profile with GCCB dscp_policy = 0x0, IS_SIPSPI_MODE_IN_SIP_SIP = 0 dscpPolicySeviceBlock = 0x0 , stream->qos_info = 0x0 Apr 9 10:10:45.450: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIUpdateRtcpSession: VQM: gccb=0x0, gccb->callId=0, ccb->ccCallID=556180 Apr 9 10:10:45.450: //556180/54CD023D81DA/SIP/Info/notify/2080/sipSPIUpdateRtcpSession: DTMF inb/oob disabled Apr 9 10:10:45.450: //556180/54CD023D81DA/SIP/State/sipSPIChangeStreamState: Stream (callid = 556180) State changed from (STREAM_CHANGING) to (STREAM_ACTIVE) Apr 9 10:10:45.450: //556180/54CD023D81DA/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1 Apr 9 10:10:45.450: //556180/54CD023D81DA/SIP/Info/info/1/sipSPIAssignStreamCallId: Assigning streamid 556180 to stream 1. Old streamid = 556180 Apr 9 10:10:45.450: //556180/54CD023D81DA/SIP/Info/info/8192/sipSPIUpdateRtcpSession: ccb->flags != LOOPBACK Apr 9 10:10:45.450: //556180/54CD023D81DA/SIP/Media/sipSPIUpdateRtcpSession: Setting do_rtcp = FALSE 0 Apr 9 10:10:45.450: //556180/54CD023D81DA/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info laddr = 10.50.66.1, lport = 20240, raddr = 10.1.100.45, rport=56340, do_rtcp=FALSE src_callid = 556180, dest_callid = 556179, stream type = voice+dtmf, stream direction = SENDRECV media_ip_addr = 10.1.100.45, vrf tableid = 0 media_addr_type = 1 negotiated_bandwidth (kbps) = 0 srtp_services = 0 nat_flag = 0 Apr 9 10:10:45.450: //556180/54CD023D81DA/SIP/Media/sipSPIUpdateRtcpSession: RTP session already created - update Apr 9 10:10:45.450: //556180/54CD023D81DA/SIP/Media/sipSPIUpdateRtpSession: stun is disabled for stream:7FFDB2049D90 Apr 9 10:10:45.450: //556180/54CD023D81DA/SIP/Info/critical/131072/sipSPIUpdateRtcpSession: Not able to Associate DSCP Profile with GCCB dscp_policy = 0x0, IS_SIPSPI_MODE_IN_SIP_SIP = 0 dscpPolicySeviceBlock = 0x0 , stream->qos_info = 0x0 Apr 9 10:10:45.450: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIUpdateRtcpSession: VQM: gccb=0x0, gccb->callId=0, ccb->ccCallID=556180 Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Info/notify/2080/sipSPIUpdateRtcpSession: DTMF inb/oob disabled Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Info/verbose/4097/sipSPI_ipip_is_escalation: local channels = 0, peer channels = 0 Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Media/sipSPIGetNewLocalMediaDirection: New Remote Media Direction = SENDRECV Present Local Media Direction = SENDRECV New Local Media Direction = SENDRECV retVal = 0 Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Info/verbose/1/sipSPIProcessMediaChanges: DSPDNLD Reqd is true. Call DoCapsInd Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Info/info/4096/ccsip_iwf_handle_generic_event: Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_default_mid_dialog_container, cur_state:S_SIP_IWF_SDP_DONE, event:E_SIP_IWF_EV_LOCAL_CAPS_IND Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Info/info/4096/is_mode_sip_sccp_do_video: Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Info/info/4096/sip_iwf_common_local_caps_hdlr: Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Info/verbose/4097/ccsip_get_rtcp_session_parameters: CURRENT VALUES: stream_callid=556180, current_seq_num=0xCFB Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Info/verbose/4097/ccsip_get_rtcp_session_parameters: NEW VALUES: stream_callid=556180, current_seq_num=0xCFB Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Info/info/1/ccsip_do_caps_ind_internal: Load DSP with codec: T38Fax, Bytes=20 Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Media/sipSPISetStreamInfo: 0 Active Streams Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Media/sipSPISetStreamInfo: Number of active streams is zero (0)! Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Media/sipSPISetStreamInfo: caps.stream_count=0,caps.stream[0].stream_type=0xFFFF, caps.stream_list.xmitFunc= Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Media/sipSPISetStreamInfo: ??unknown??, caps.stream_list.context= Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Media/sipSPISetStreamInfo: 0x0 (rtp_fork_id) Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Info/info/32/sipSPISetDTMFRelayMode: Set DSP for dtmf-relay = CC_CAP_DTMF_RELAY_INBAND_VOICE_AND_OOB Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Info/info/10241/sip_set_modem_caps: Preferred (or the one that came from DSM) modem relay=0, from CLI config=0 Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Info/verbose/12288/sipSPIGetModemInfoPerCall: peer_callID=556179 Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Info/info/8193/sip_set_modem_caps: Disabling Modem Relay... Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Info/info/8193/sip_set_modem_caps: Negotiation already Done. Set negotiated Modem caps and generate SDP Xcap list Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Info/info/8193/sip_set_modem_caps: Modem Relay & Passthru both disabled Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Info/info/8193/sip_set_modem_caps: nse payload = 0, ptru mode = 0, ptru-codec=1, redundancy=0, xid=0, relay=0, sprt-retry=12, latecncy=200, compres-dir=3, dict=1024, strnlen=32 Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:CNFSM_NO_STATE_CHANGE Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Info/info/1/sipSPIIncomingCallSDP: SDP already there use old SDP and update media if needed Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Info/verbose/1/sipSPIUpdateSrcSdpFixedPart: RTP port already reserved for stream 1, src_port=20240 Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Error/sipIPIP_add_bandwidth_line: Unknown media_type = 11 Apr 9 10:10:45.451: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/sipSPISetMediaDirectionForStream: Setting Media direction SENDRECV for stream 1 Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Info/info/1/sipSPIUpdateSrcSdpVariablePart: Setting stream 1 portnum to 20240 Apr 9 10:10:45.451: //556180/54CD023D81DA/SIP/Info/notify/1/sipSPIUpdateSrcSdpVariablePart: SIP update src sdp, negoitated codec 17, payload type 255 Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/info/131080/sipSPIBwCacCalcMaxFaxBandwidth: Negotiated T.38 Fax Rate 9600 (bps) Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/info/131080/sipSPIBwCacCalcMaxFaxBandwidth: Max T.38 Fax BW (bps) 9600 fax bit rate 15680 Fax HS Red 0 Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/info/131072/sipSPIBwCacUpdateAccountedBw: bwcac update accounted BW Option 2 flow mode flow-through audio bw 0 bps video bw 0 bps fax bw 15680 bps total bw 15680 bps accounted bw 80000 bps Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/info/131072/sipSPIBwCacUpdateAccountedBw: bwcac update accounted bw (mid offer) accounted bw unchanged 80000 delta -64320 Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/info/139264/sipSPIBwCacUpdateInterfaceBw: NOP (no interface change) Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/notify/131072/ccsip_api_request_offer: Deffering QoS reservation for MID-CALL Invite Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/info/133120/sipSPIBwCacIsDialPeerBwAvailable: bwcac NOP dial-peer bw available tag 500 Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/info/131072/sipSPIBwCacVerifyBwThreshold: bwcac verify bw threshold, bw available allow call total bw 15680 bps Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/verbose/1/ccsip_api_request_offer: send_local_answer == TRUE, invoke ccsip_call_response_answser Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/info/131080/sipSPIBwCacCalcMaxFaxBandwidth: Negotiated T.38 Fax Rate 9600 (bps) Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/info/131080/sipSPIBwCacCalcMaxFaxBandwidth: Max T.38 Fax BW (bps) 9600 fax bit rate 15680 Fax HS Red 0 Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/info/131072/sipSPIBwCacUpdateAccountedBw: bwcac update accounted BW Option 3 flow mode flow-through audio bw 0 bps video bw 0 bps fax bw 15680 bps total bw 15680 bps accounted bw 80000 bps Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/verbose/4096/sipSPIBwCacUpdateDialPeerBw: NOP Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/info/139264/sipSPIBwCacUpdateInterfaceBw: NOP (no interface change) Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/info/131072/sipSPIBwCacUpdateAccountedBw: bwcac update accounted bw (mid answer) accounted bw restored to previous 80000 delta 0 Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/verbose/1/ccsip_api_request_offer: Response 200 OK locally Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/notify/131073/sipSPIUpdateStreamQoSAttributes: 9 a-line(s) found for stream 1 Apr 9 10:10:45.452: //-1/xxxxxxxxxxxx/SIP/Info/info/1/sipSPICheckForSDPModification: prev send SDP size = 311, curr send SDP size = 311 Apr 9 10:10:45.452: //-1/xxxxxxxxxxxx/SIP/Info/info/1/sipSPICheckForSDPModification: prev send SDP and curr send SDP are same Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/info/1/sipSPIHandleSDPOwnerVersionIDChange: SDP owner_version ID not incremented .. Apr 9 10:10:45.452: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_MEDIA_EVENT Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/verbose/8192/ccsip_call_response_answer: RTP_LPBK == FALSE, checkpoint HA data Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/State/sipSPIChangeState: 0x7FFDA8AFBAB8 : State change from (STATE_ACTIVE, SUBSTATE_NONE) to (STATE_MIDCALL_LOCAL_RESP_PENDING, SUBSTATE_NONE) Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/verbose/4096/sipSPIHandleIncomingMidCallInvite: ccsip_api_request_offer returned: SIP_SUCCESS Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/verbose/4096/sipSPISendInviteResponse: Dialog State: [2] Apr 9 10:10:45.452: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB3339018 with refCount = 1 Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_RESP Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Event/Session-Timer/sipSTSLMain: dir:1, method:102, resp_code:100, container:7FFDB3326BF8 Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/critical/8192/Session-Timer/sipSTSLValidateSessRefreshMsg: Ignoring 1xx response for session timer processing Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 3 event Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Apr 9 10:10:45.452: //556180/54CD023D81DA/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Apr 9 10:10:45.453: //556180/54CD023D81DA/SIP/Info/info/4096/sipSPISendInviteResponse: Associated container=0x7FFDB3326BF8 to Invite Response 100 Apr 9 10:10:45.453: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Apr 9 10:10:45.453: //556180/54CD023D81DA/SIP/Transport/sipSPITransportSendMessage: msg=0x7FFDB3339018, addr=10.1.128.135, port=54378, sentBy_port=5060, local_addr=10.50.66.1, is_req=0, transport=2, switch=0, callBack=0x0 Apr 9 10:10:45.453: //556180/54CD023D81DA/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:10:45.453: //556180/54CD023D81DA/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:10:45.453: //556180/54CD023D81DA/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 9 10:10:45.453: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x7FFDA0BDA5E8, addr=10.1.128.135, port=5060, local_addr=10.50.66.1, unregistering context=0x7FFDA8AFBAB8 Apr 9 10:10:45.453: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x7FFDA8AFBAB8 from the connection=0x7FFDA0F7BF18 context list Apr 9 10:10:45.453: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x7FFDB3339018, addr=10.1.128.135, port=54378, local_addr=10.50.66.1, connId=63 vrfid=0 for TCP Apr 9 10:10:45.453: //556180/54CD023D81DA/SIP/Info/verbose/4608/sipSPIProcessContactInfo: Previous Hop 10.1.128.135:5060 Apr 9 10:10:45.453: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x7FFD9D9341A0) counter, current msg->refCount = 2 Apr 9 10:10:45.453: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 29 Apr 9 10:10:45.453: //556180/54CD023D81DA/SIP/Info/info/4096/act_handle_app_media_event: method = 102 state = 16 Apr 9 10:10:45.453: //556180/54CD023D81DA/SIP/Info/info/4096/act_handle_app_media_event: Received media sip event SIP_RESPONSE_ANSWER Apr 9 10:10:45.453: //556180/54CD023D81DA/SIP/Info/info/1/sipSPIProcessHoldTimerForCall: Media IP Addr 10.1.100.45, RTCP Type 3 Apr 9 10:10:45.453: //556180/54CD023D81DA/SIP/Info/info/4096/sipSPIStopHoldTimer: Stopping hold timer Apr 9 10:10:45.453: //556180/54CD023D81DA/SIP/Info/verbose/4096/sipSPISendInviteResponse: Dialog State: [2] Apr 9 10:10:45.453: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB2D061F8 with refCount = 1 Apr 9 10:10:45.453: //556180/54CD023D81DA/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_RESP Apr 9 10:10:45.453: //556180/54CD023D81DA/SIP/Event/Session-Timer/sipSTSLMain: dir:1, method:102, resp_code:200, container:7FFDB3328A70 Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/Info/info/8192/Session-Timer/sipSTSLSRRespSend: Session expires header is received in the request, starting the session timer Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/Info/info/8192/Session-Timer/sipSTSLStartSessionTimer: Started Session Expiry Timer with duration:14368000 Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/Info/info/8192/Session-Timer/sipSTSLMain: SE: 14400;refresher:uas peer refresher:none, flags:1, posted event:E_STSL_INVALID_PEER_EVENT, reason:4 Configured SE:1800, Configured Min-SE:1800 Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 8 event Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/Info/info/4096/ccsip_offer_ans_handle_sent_sdp: Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/State/ccsip_cnfsm_debugs: OA:cur_container:ccsip_offer_ans_main_container, cur_state:S_SIP_MID_DIALOG_IDLE, event:E_SIP_INVITE_RESP_SDP_SENT Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/Info/info/4096/ccsip_offer_ans_is_invite_resp_offer_valid: FALSE Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/Info/info/4096/ccsip_offer_ans_process_event: O/A - cnfsm ret 2 Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/Info/notify/16384/sipSPIAppUpdateToTag: This is hold/resume request, so skip update, call with callid: 556180 Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/Info/notify/16384/sipSPIAppAddCallInfoUI: This is hold/resume request, so skip update, call with callid: 556180 Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/Info/notify/4096/sipSPISendInviteResponse: Add Accept was successful 0 Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/Info/verbose/4096/sipSPISendInviteResponse: Transaction active. Facilities will be queued. SIP: (556180) Group (a= group line) attribute, level 65535 instance 1 not found. Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/Info/info/34816/sipSPIGetCallExtensionSupported: anat enabled, src_sdp and dest_sdp available, should be a midcall request Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/Info/info/4096/sipSPISendInviteResponse: Associated container=0x7FFDB3328A70 to Invite Response 200 Apr 9 10:10:45.454: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 311 Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/Transport/sipSPISendInviteResponse: Sending 200OK Response to the Transport Layer Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/Transport/sipSPITransportSendMessage: msg=0x7FFDB2D061F8, addr=10.1.128.135, port=54378, sentBy_port=5060, local_addr=10.50.66.1, is_req=0, transport=2, switch=0, callBack=0x7FFE0B2376A0 Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:10:45.454: //556180/54CD023D81DA/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 9 10:10:45.514: //556180/54CD023D81DA/SIP/Info/verbose/4096/force_internal_queue_lookup: There are 1 events on the internal queue Apr 9 10:10:45.514: //556180/54CD023D81DA/SIP/Info/info/4096/force_internal_queue_lookup: Dequeued event SIPSPI_EV_CC_CODEC_LOCAL_DNLD_DONE from internal buffer queue Apr 9 10:10:45.515: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB2D061F8 Apr 9 10:10:45.515: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 21 Apr 9 10:10:48.021: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x7FFDA8BA1630) with key=[567290] to table Apr 9 10:10:48.021: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init: Apr 9 10:10:48.021: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init: Apr 9 10:10:48.021: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised.. Apr 9 10:10:48.021: //-1/000000000000/SIP/Info/verbose/4097/ccsip_platform_init_ccb: Initialising rtp session queue Apr 9 10:10:48.021: //556181/000000000000/SIP/State/sipSPIChangeState: 0x7FFDA8BA1630 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Apr 9 10:10:48.021: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 37 Apr 9 10:10:48.022: //556181/000000000000/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable: Adding call id 87C95 to table Apr 9 10:10:48.022: //556181/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Apr 9 10:10:48.022: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.50.66.1 for SIP Apr 9 10:10:48.022: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.50.66.1 for SIP Apr 9 10:10:48.022: //556181/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 10.50.66.1 Apr 9 10:10:48.022: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 10.50.66.1 Apr 9 10:10:48.022: //556181/000000000000/SIP/Info/verbose/4096/sipSPIUaddCcbToUACTable: ****Adding to UAC table.0x7FFDA8BA1630 582F8EDB-3B0411E8-93DFAD25-DD7BDD2E@10.50.66.1 Apr 9 10:10:48.022: //556181/000000000000/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x7FFDA8BA1630 key=582F8EDB-3B0411E8-93DFAD25-DD7BDD2E@10.50.66.1 balance 0 Apr 9 10:10:48.022: //556181/000000000000/SIP/State/sipSPIChangeState: 0x7FFDA8BA1630 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_NONE) Apr 9 10:10:48.022: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB34B9C40 with refCount = 1 Apr 9 10:10:48.022: //556181/000000000000/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 15 event Apr 9 10:10:48.022: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone MEZ_SZ to SIP default timezone = GMT Apr 9 10:10:48.022: //556181/000000000000/SIP/Error/sipSPIAddPrivacyHeader: Orig Container is NULL...should have value except in case of sending OOD Options ping. Apr 9 10:10:48.022: //556181/000000000000/SIP/Error/sipSPIAddAssertedIDHeader: Orig Container is NULL...should have value except in case of sending OOD Options ping. Apr 9 10:10:48.022: //556181/000000000000/SIP/Error/sipSPIAddPreferredIDHeader: Orig Container is NULL...should have value except in case of sending OOD Options ping. Apr 9 10:10:48.022: //556181/000000000000/SIP/Info/info/4096/sipSPISendOptionsRequest: Associated container=0x7FFDB3325400 to Options Apr 9 10:10:48.022: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Apr 9 10:10:48.022: //556181/000000000000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Dial peer configuration, Switch Transport is FALSE Apr 9 10:10:48.022: //556181/000000000000/SIP/Transport/sipSPITransportSendMessage: msg=0x7FFDB34B9C40, addr=10.1.192.132, port=5060, sentBy_port=0, local_addr=10.50.66.1, is_req=1, transport=2, switch=0, callBack=0x7FFE0B237DB0 Apr 9 10:10:48.022: //556181/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:10:48.022: //556181/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:10:48.022: //556181/000000000000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 9 10:10:48.022: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.1.192.132, rport:5060 with laddr:10.50.66.1 Apr 9 10:10:48.022: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x7FFDA8BA1630 with connection=0x7FFDA0F7D498 context list Apr 9 10:10:48.022: //556181/000000000000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x7FFDB34B9C40 Apr 9 10:10:48.022: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x7FFDB34B9C40, addr=10.1.192.132, port=5060, local_addr=10.50.66.1, connId=60 vrfid=0 for TCP Apr 9 10:10:48.023: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_tcp_queue_event: Event type: send msg, connid: 60, fd: 4 Apr 9 10:10:48.023: //556181/000000000000/SIP/Msg/ccsipDisplayMsg: Sent: OPTIONS sip:10.1.192.132:5060 SIP/2.0 Via: SIP/2.0/TCP 10.50.66.1:5060;branch=z9hG4bK56C7C1308 From: ;tag=7AA1E7AF-1FAB To: Date: Mon, 09 Apr 2018 08:10:48 GMT Call-ID: 582F8EDB-3B0411E8-93DFAD25-DD7BDD2E@10.50.66.1 User-Agent: Cisco-SIPGateway/IOS-15.4.3.S4 Max-Forwards: 70 CSeq: 101 OPTIONS Contact: Content-Length: 0 Apr 9 10:10:48.023: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB34B9C40 Apr 9 10:10:48.077: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 4 to index 60 Apr 9 10:10:48.077: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB34B9C40 with refCount = 1 Apr 9 10:10:48.077: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB3098A28 with refCount = 1 Apr 9 10:10:48.077: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB34B9C40 Apr 9 10:10:48.077: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Apr 9 10:10:48.077: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x7FFDA0BDA5E8 Apr 9 10:10:48.077: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x7FFDA0BDA5E8, addr=10.1.192.132, port=5060, local_addr=10.50.66.1, connid=60, transport=TCP Apr 9 10:10:48.077: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 5060 connId 60 Apr 9 10:10:48.077: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Apr 9 10:10:48.078: //556181/000000000000/SIP/Info/info/1024/sipSPIMatchRespToReqTran: removing unneeded z9hG4bK56C7C1308 from via branch list Apr 9 10:10:48.078: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x7FFDB3098A28) counter, current msg->refCount = 2 Apr 9 10:10:48.078: //556181/000000000000/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 503 Service Unavailable Via: SIP/2.0/TCP 10.50.66.1:5060;branch=z9hG4bK56C7C1308 From: ;tag=7AA1E7AF-1FAB To: ;tag=2002442784 Date: Mon, 09 Apr 2018 08:10:48 GMT Call-ID: 582F8EDB-3B0411E8-93DFAD25-DD7BDD2E@10.50.66.1 CSeq: 101 OPTIONS Warning: 399 CH-SV01777 "Unable to find a device handler for the request received on port 51036 from 10.50.66.1" Content-Length: 0 Apr 9 10:10:48.078: //556181/000000000000/SIP/Info/verbose/1024/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX Apr 9 10:10:48.078: //556181/000000000000/SIP/Info/info/4096/sipSPIHandle_ccsip_api_options_result: Optionsping feature disabled SIP_ADDR_INVALID = FALSE, Response_code = 503, Source = External, PingStatus NOT SAVED in Stack. Apr 9 10:10:48.078: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x7FFDB3098A28) counter, current msg->refCount = 1 Apr 9 10:10:48.078: //556181/000000000000/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 87C95 Apr 9 10:10:48.078: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[567290] removed. Apr 9 10:10:48.078: //556181/000000000000/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x7FFDA8BA1630 key=582F8EDB-3B0411E8-93DFAD25-DD7BDD2E@10.50.66.1 Apr 9 10:10:48.078: //556181/000000000000/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Apr 9 10:10:48.078: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x7FFDA0BDA5E8, addr=10.1.192.132, port=5060, local_addr=10.50.66.1, unregistering context=0x7FFDA8BA1630 Apr 9 10:10:48.078: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x7FFDA8BA1630 from the connection=0x7FFDA0F7D498 context list Apr 9 10:10:48.078: //556181/000000000000/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Apr 9 10:10:48.078: //556181/000000000000/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer Apr 9 10:10:48.078: //556181/000000000000/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x7FFDA8BA1630 Apr 9 10:10:48.078: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[567290] Apr 9 10:10:48.078: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB3098A28 Apr 9 10:10:49.283: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 2 to index 63 Apr 9 10:10:49.283: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB3339018 with refCount = 1 Apr 9 10:10:49.283: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB3098A28 with refCount = 1 Apr 9 10:10:49.283: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB3339018 Apr 9 10:10:49.283: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Apr 9 10:10:49.283: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Apr 9 10:10:49.283: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x7FFDA0BDA5E8, addr=10.1.128.135, port=54378, local_addr=10.50.66.1, connid=63, transport=TCP Apr 9 10:10:49.283: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 54378 connId 63 Apr 9 10:10:49.283: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: OPTIONS sip:10.50.66.1:5060 SIP/2.0 Via: SIP/2.0/TCP 10.1.128.135:5060;branch=z9hG4bK8f422472638a2a From: ;tag=1996443022 To: Date: Mon, 09 Apr 2018 08:10:49 GMT Call-ID: 81f69000-acb12009-4dd38f-8780010a@10.1.128.135 User-Agent: Cisco-CUCM10.5 CSeq: 101 OPTIONS Contact: Max-Forwards: 0 Content-Length: 0 Apr 9 10:10:49.283: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Apr 9 10:10:49.283: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x7FFDA8BA1630) with key=[567291] to table Apr 9 10:10:49.283: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init: Apr 9 10:10:49.283: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init: Apr 9 10:10:49.283: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised.. Apr 9 10:10:49.283: //-1/000000000000/SIP/Info/verbose/4097/ccsip_platform_init_ccb: Initialising rtp session queue Apr 9 10:10:49.283: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.1.128.135,Port 54378, Transport 2, SentBy Port 5060vrfid 0 Apr 9 10:10:49.283: //-1/000000000000/SIP/Info/verbose/4608/sipSPISipIncomingMsg: copy the natted transport info to ccb natted dest: 10.1.128.135:54378,natted src: 10.50.66.1:5060, natted transport: 2 Apr 9 10:10:49.283: //-1/000000000000/SIP/Info/info/1024/sipSPISipIncomingMsg: sip via host 10.1.128.135 Apr 9 10:10:49.283: //-1/000000000000/SIP/Info/info/9216/sipSPISipIncomingMsg: sip nat auto detect 0 Apr 9 10:10:49.284: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Apr 9 10:10:49.284: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.50.66.1 for SIP Apr 9 10:10:49.284: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.50.66.1 for SIP Apr 9 10:10:49.284: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 10.50.66.1 Apr 9 10:10:49.284: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 10.50.66.1 Apr 9 10:10:49.284: //-1/58F01F8A93E0/SIP/State/sipSPIChangeState: 0x7FFDA8BA1630 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Apr 9 10:10:49.284: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.1.128.135,Port 54378, Transport 2, SentBy Port 5060vrfid 0 Apr 9 10:10:49.284: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone MEZ_SZ to SIP default timezone = GMT Apr 9 10:10:49.284: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.1.128.135,Port 54378, Transport 2, SentBy Port 5060vrfid 0 Apr 9 10:10:49.284: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x7FFDB3098A28) counter, current msg->refCount = 2 Apr 9 10:10:49.284: //-1/xxxxxxxxxxxx/SIP/Error/httpish_msg_free: Freeing NULL pointer! Apr 9 10:10:49.284: //556182/58F01F8A93E0/SIP/Info/verbose/1024/sipSPIGetViaHostInURLFormat: VIA URL:sip:10.1.128.135:5060, Host:10.1.128.135 Apr 9 10:10:49.284: //556182/58F01F8A93E0/SIP/Info/verbose/67584/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: : Apr 9 10:10:49.284: //556182/58F01F8A93E0/SIP/Error/sipSPIGetPeerByCalledPartyId: input arg error Apr 9 10:10:49.284: //556182/58F01F8A93E0/SIP/Info/critical/10240/sipSPIGetCallConfig: No match found for P-Called-Party-ID Apr 9 10:10:49.284: //556182/58F01F8A93E0/SIP/Error/sipSPIUpdateCallInfo: input argument error Apr 9 10:10:49.284: //556182/58F01F8A93E0/SIP/Info/verbose/1024/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header Apr 9 10:10:49.284: //556182/58F01F8A93E0/SIP/Info/verbose/2048/sipSPIGetCallConfig: Media Antitrombone disabled Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/8192/sipSPISetMediaFlowMode: Storing the configured mode as FLOW-THROUGH Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/2304/sipSPISetMediaFlowMode: xcoder high-density disabled Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/8192/sipSPISetMediaFlowMode: Flow Mode set to FLOW_THROUGH Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/10240/sipSPIGetCallConfig: Non dial peer leg - using RTP Supported Codecs Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 18 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 0 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 8 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 9 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 4 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 2 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 15 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 3 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/critical/32768/ccsip_ipip_media_forking_update_preferred_codec: MF: Not a Forked SIP leg.. Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/verbose/12288/sipSPIGetModemInfoPerCall: peer_callID=0 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/8192/sipSPIGetModemConfig: From Config: Modem NSE payload = 100, Passthrough = 4, Modem relay = 0, Gw-Xid = 1 SPRT latency 200, SPRT Retries = 12, Dict Size = 1024 String Len = 32, Compress dir = 3 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Error/ccsip_ipip_media_forking_anchor_leg_config: MF: Dial-peer is absent.. Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/36864/sipSPIMFChangeState: MF: Prev state = 0 & New state = -1 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/32768/ccsip_ipip_media_forking_anchor_leg_reset: MF: Anchor leg config reset done... Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Error/ccsip_ipip_media_forking_intra_frame_request_config: MF:video profile Dial-peer is absent.. Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/verbose/8192/sipSPICheckFAAnatAssymetricOrDO2EO: Not a SIP-SIP call or not in FA mode Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/2049/populate_vcc_data: Non dial peer leg - using RTP Supported Codecs Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 18 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 0 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 8 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 9 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 4 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 2 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 15 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 3 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/notify/8192/sipSPISetOverlapConfiguration: Overlap signaling: FALSE: Endpt: SIP Trunk Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/verbose/10240/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/verbose/2048/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/notify/10240/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled Apr 9 10:10:49.285: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x7FFDB3098A28) counter, current msg->refCount = 1 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/notify/6/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/verbose/513/resolve_media_ip_address_to_bind: peer_tag=0 Apr 9 10:10:49.285: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_media_ip_address_to_bind: VRF id = 0 Apr 9 10:10:49.285: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.50.66.1 for SIP Apr 9 10:10:49.285: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.50.66.1 for SIP Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.50.66.1 Apr 9 10:10:49.285: //556182/58F01F8A93E0/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Apr 9 10:10:49.286: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.50.66.1 for SIP Apr 9 10:10:49.286: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.50.66.1 for SIP Apr 9 10:10:49.286: //556182/58F01F8A93E0/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 10.50.66.1 Apr 9 10:10:49.286: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 10.50.66.1 Apr 9 10:10:49.286: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_OPTIONS_RESP Apr 9 10:10:49.286: //556182/58F01F8A93E0/SIP/Info/info/4096/sact_idle_new_message_options: ccsip_api_options_ind returned: SIP_SUCCESS Apr 9 10:10:49.286: //556182/58F01F8A93E0/SIP/State/sipSPIChangeState: 0x7FFDA8BA1630 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_NONE) Apr 9 10:10:49.286: //556182/58F01F8A93E0/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x7FFDA8BA1630 key=81f69000-acb12009-4dd38f-8780010a@10.1.128.135 balance 0 Apr 9 10:10:49.286: //556182/58F01F8A93E0/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable: Adding call id 87C96 to table Apr 9 10:10:49.286: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 38 Apr 9 10:10:49.286: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDA4A8D9B0 with refCount = 1 Apr 9 10:10:49.286: //556182/58F01F8A93E0/SIP/Info/info/4096/sipSPISendOptionsResponse: Associated container=0x7FFDB3324428 to Options Response Apr 9 10:10:49.286: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 365 Apr 9 10:10:49.286: //556182/58F01F8A93E0/SIP/Transport/sipSPITransportSendMessage: msg=0x7FFDA4A8D9B0, addr=10.1.128.135, port=54378, sentBy_port=5060, local_addr=10.50.66.1, is_req=0, transport=2, switch=0, callBack=0x7FFE0B237E00 Apr 9 10:10:49.286: //556182/58F01F8A93E0/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:10:49.286: //556182/58F01F8A93E0/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:10:49.286: //556182/58F01F8A93E0/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 9 10:10:49.286: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x7FFDA4A8D9B0, addr=10.1.128.135, port=54378, local_addr=10.50.66.1, connId=63 vrfid=0 for TCP Apr 9 10:10:49.286: //556182/58F01F8A93E0/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 87C96 Apr 9 10:10:49.286: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[567291] removed. Apr 9 10:10:49.287: //556182/58F01F8A93E0/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x7FFDA8BA1630 key=81f69000-acb12009-4dd38f-8780010a@10.1.128.135 Apr 9 10:10:49.287: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB3098A28 Apr 9 10:10:49.287: //556182/58F01F8A93E0/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Apr 9 10:10:49.287: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x7FFDA0BDA5E8, addr=10.1.128.135, port=54378, local_addr=10.50.66.1, unregistering context=0x7FFDA8BA1630 Apr 9 10:10:49.287: //556182/58F01F8A93E0/SIP/Transport/sipSPITransportContextCleanup: Could not purge context gcb=0x7FFDA8BA1630 from the connection; gcb might be locked Apr 9 10:10:49.287: //556182/58F01F8A93E0/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Apr 9 10:10:49.287: //556182/58F01F8A93E0/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer Apr 9 10:10:49.287: //556182/58F01F8A93E0/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x7FFDA8BA1630 Apr 9 10:10:49.287: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[567291] Apr 9 10:10:49.287: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPITransportSendMessage: gcb has cleanedup, Done with send operations for this context Apr 9 10:10:49.287: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[567291] Apr 9 10:10:49.287: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_tcp_queue_event: Event type: send msg, connid: 63, fd: 2 Apr 9 10:10:49.287: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 200 OK Via: SIP/2.0/TCP 10.1.128.135:5060;branch=z9hG4bK8f422472638a2a From: ;tag=1996443022 To: ;tag=7AA1EC9D-2545 Date: Mon, 09 Apr 2018 08:10:49 GMT Call-ID: 81f69000-acb12009-4dd38f-8780010a@10.1.128.135 Server: Cisco-SIPGateway/IOS-15.4.3.S4 CSeq: 101 OPTIONS Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER Allow-Events: telephone-event Accept: application/sdp Supported: 100rel,timer,resource-priority,replaces,sdp-anat Content-Type: application/sdp Content-Length: 365 v=0 o=CiscoSystemsSIP-GW-UserAgent 6372 7849 IN IP4 10.50.66.1 s=SIP Call c=IN IP4 10.50.66.1 t=0 0 m=audio 0 RTP/AVP 18 0 8 9 4 2 15 3 c=IN IP4 10.50.66.1 m=image 0 udptl t38 c=IN IP4 10.50.66.1 a=T38FaxVersion:0 a=T38MaxBitRate:9600 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:200 a=T38FaxMaxDatagram:320 a=T38FaxUdpEC:t38UDPRedundancy Apr 9 10:10:49.287: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDA4A8D9B0 Apr 9 10:10:49.734: ISDN Se0/1/0:15 Q931: RX <- DISCONNECT pd = 8 callref = 0x0001 Cause i = 0x8490 - Normal call clearing Progress Ind i = 0x8288 - In-band info or appropriate now available Apr 9 10:10:49.735: ISDN Se0/1/0:15 Q931: call_disc: PI received in disconnect; Postpone sending RELEASE for callid 0x20C Apr 9 10:10:49.736: //556180/54CD023D81DA/SIP/Info/verbose/4096/ccsip_ipip_media_service_get_event_data: Event id = 18 Apr 9 10:10:49.736: //556180/54CD023D81DA/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_XCODER_RESET_STREAM Apr 9 10:10:49.736: //556180/54CD023D81DA/SIP/Info/verbose/256/sipSPIResetXcoder: *****CLEANING UP XCODER RESOURCES***** Apr 9 10:10:49.736: //556180/54CD023D81DA/SIP/Info/verbose/256/sipSPIResetXcoder: *****CLEANING UP XCODER RESOURCES***** Apr 9 10:10:49.736: //556180/54CD023D81DA/SIP/Info/verbose/256/sipSPIResetXcoder: Xcoder resource already cleaned up Apr 9 10:10:49.736: //556180/54CD023D81DA/SIP/State/ccsip_cnfsm_debugs: IPIPMS:next_state:S_IPIP_MEDIA_SERV_STATE_IDLE Apr 9 10:10:49.736: //556180/54CD023D81DA/SIP/Media/sipSPIUpdateRtpSession: stun is disabled for stream:7FFDB2049D90 Apr 9 10:10:49.738: //556180/54CD023D81DA/SIP/Info/verbose/8192/ccsip_call_statistics: Requesting stats for callid=556180 Apr 9 10:10:49.738: //556180/54CD023D81DA/SIP/Info/verbose/4096/ccsip_ipip_media_service_get_event_data: Event id = 29 Apr 9 10:10:49.738: //556180/54CD023D81DA/SIP/Info/critical/32768/ccsip_ipip_media_forking_post_event: MF: Not a Anchor SIP leg.. Apr 9 10:10:49.738: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT Apr 9 10:10:49.738: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 8 Apr 9 10:10:49.738: //556180/54CD023D81DA/SIP/Info/info/133120/sipSPIBwCacReleaseDialPeerBw: bwcac dial-peer bw 80 Kbps released for tag 500 active bw 0 Kbps Apr 9 10:10:49.738: //556180/54CD023D81DA/SIP/Info/info/131072/sipSPIBwCacReleaseInterfaceBw: bwcac releasing interface Loopback0 bw 80 Kbps Apr 9 10:10:49.738: //556180/54CD023D81DA/SIP/Info/info/131072/sipSPIBwCacReleaseAccountedBw: bwcac released accounted bw 80000 bps Apr 9 10:10:49.738: //556180/54CD023D81DA/SIP/Info/notify/4096/act_active_disconnect: Disconnect deferred, as stats request pending Apr 9 10:10:49.738: //556180/54CD023D81DA/SIP/Info/info/4096/sipSPISetCommonTimer: Started generic timer type 2 for 240000 millisecs Apr 9 10:10:49.751: //556180/54CD023D81DA/SIP/Info/verbose/32768/ccsip_indicate_rt_packet_stats: Processing stats for callid=556180, proc_id=1 Apr 9 10:10:49.751: //556180/54CD023D81DA/SIP/Info/verbose/4096/ccsip_ipip_media_service_get_event_data: Event id = 29 Apr 9 10:10:49.752: //556180/54CD023D81DA/SIP/Info/critical/32768/ccsip_ipip_media_forking_post_event: MF: Not a Anchor SIP leg.. Apr 9 10:10:49.752: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT Apr 9 10:10:49.752: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 8 Apr 9 10:10:49.752: //556180/54CD023D81DA/SIP/Info/info/4096/act_active_disconnect: act_active_disconnect: Disconnect now.. no defer BYE.. Apr 9 10:10:49.752: //556180/54CD023D81DA/SIP/Info/info/4096/sipSPIStopHoldTimer: Stopping hold timer Apr 9 10:10:49.752: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB3098A28 with refCount = 1 Apr 9 10:10:49.752: //556180/54CD023D81DA/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 3 event Apr 9 10:10:49.752: //556180/54CD023D81DA/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Apr 9 10:10:49.752: //556180/54CD023D81DA/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Apr 9 10:10:49.752: //556180/54CD023D81DA/SIP/Info/info/4096/sipSPIStopHoldTimer: Stopping hold timer Apr 9 10:10:49.752: //556180/54CD023D81DA/SIP/Info/info/4096/sipSPISendBye: Associated container=0x7FFDB3326238 to Bye Apr 9 10:10:49.752: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Apr 9 10:10:49.752: //556180/54CD023D81DA/SIP/Transport/sipSPISendBye: Sending BYE to the transport layer Apr 9 10:10:49.752: //556180/54CD023D81DA/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Dial peer configuration, Switch Transport is FALSE Apr 9 10:10:49.752: //556180/54CD023D81DA/SIP/Transport/sipSPITransportSendMessage: msg=0x7FFDB3098A28, addr=10.1.128.135, port=5060, sentBy_port=0, local_addr=10.50.66.1, is_req=1, transport=2, switch=0, callBack=0x7FFE0B2371A0 Apr 9 10:10:49.752: //556180/54CD023D81DA/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:10:49.752: //556180/54CD023D81DA/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:10:49.752: //556180/54CD023D81DA/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 9 10:10:49.752: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x7FFDA0BDA5E8, addr=10.1.128.135, port=54378, local_addr=10.50.66.1, unregistering context=0x7FFDA8AFBAB8 Apr 9 10:10:49.752: //556180/54CD023D81DA/SIP/Transport/sipSPITransportSendMessage: Could not purge context gcb=0x7FFDA8AFBAB8 from the connection; gcb might be locked Apr 9 10:10:49.753: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.1.128.135, rport:5060 with laddr:10.50.66.1 Apr 9 10:10:49.753: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x7FFDA8AFBAB8 with connection=0x7FFDA0F7BF18 context list Apr 9 10:10:49.753: //556180/54CD023D81DA/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x7FFDB3098A28 Apr 9 10:10:49.753: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x7FFDB3098A28, addr=10.1.128.135, port=5060, local_addr=10.50.66.1, connId=65 vrfid=0 for TCP Apr 9 10:10:49.753: //556180/54CD023D81DA/SIP/Info/info/512/sentByeDisconnecting: Sent Bye Request, starting DisconnectTimer Apr 9 10:10:49.753: //556180/54CD023D81DA/SIP/State/sipSPIChangeState: 0x7FFDA8AFBAB8 : State change from (STATE_ACTIVE, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE) Apr 9 10:10:49.753: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_tcp_queue_event: Event type: send msg, connid: 65, fd: 7 Apr 9 10:10:49.753: //556180/54CD023D81DA/SIP/Msg/ccsipDisplayMsg: Sent: BYE sip:+35020002501@10.1.128.135:5060;transport=tcp SIP/2.0 Via: SIP/2.0/TCP 10.50.66.1:5060;branch=z9hG4bK56C7D22DB From: ;tag=7AA1D189-2377 To: ;tag=20448815~066d7f19-322a-43ba-8eca-ef58947b04ca-62721385 Date: Mon, 09 Apr 2018 08:10:45 GMT Call-ID: 54CE3B25-3B0411E8-93DEAD25-DD7BDD2E@10.50.66.1 User-Agent: Cisco-SIPGateway/IOS-15.4.3.S4 Max-Forwards: 70 Timestamp: 1523261449 CSeq: 102 BYE Reason: Q.850;cause=16 Content-Length: 0 Apr 9 10:10:49.753: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB3098A28 Apr 9 10:10:49.754: ISDN Se0/1/0:15 Q931: TX -> RELEASE pd = 8 callref = 0x8001 Apr 9 10:10:49.810: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 7 to index 65 Apr 9 10:10:49.810: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB2D97B60 with refCount = 1 Apr 9 10:10:49.810: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB3098A28 with refCount = 1 Apr 9 10:10:49.810: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB2D97B60 Apr 9 10:10:49.810: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Apr 9 10:10:49.810: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x7FFDA0BDA5E8 Apr 9 10:10:49.810: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x7FFDA0BDA5E8, addr=10.1.128.135, port=5060, local_addr=10.50.66.1, connid=65, transport=TCP Apr 9 10:10:49.810: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 5060 connId 65 Apr 9 10:10:49.810: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Apr 9 10:10:49.811: //556180/54CD023D81DA/SIP/Info/info/1024/sipSPIMatchRespToReqTran: removing unneeded z9hG4bK56C7D22DB from via branch list Apr 9 10:10:49.811: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x7FFDB3098A28) counter, current msg->refCount = 2 Apr 9 10:10:49.811: //556180/54CD023D81DA/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 200 OK Via: SIP/2.0/TCP 10.50.66.1:5060;branch=z9hG4bK56C7D22DB From: ;tag=7AA1D189-2377 To: ;tag=20448815~066d7f19-322a-43ba-8eca-ef58947b04ca-62721385 Date: Mon, 09 Apr 2018 08:10:49 GMT Call-ID: 54CE3B25-3B0411E8-93DEAD25-DD7BDD2E@10.50.66.1 Server: Cisco-CUCM10.5 CSeq: 102 BYE Content-Length: 0 Apr 9 10:10:49.811: //556180/54CD023D81DA/SIP/Info/verbose/1024/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX Apr 9 10:10:49.811: //556180/54CD023D81DA/SIP/Info/sact_disconnecting_new_message_response: [sact_disconnecting_new_message_response] Received Response Class [2] Method Code [103] Apr 9 10:10:49.811: //556180/54CD023D81DA/SIP/Info/info/4096/sipSPISetCommonTimer: Stopping timer type 2 to start 2 Apr 9 10:10:49.811: //556180/54CD023D81DA/SIP/Info/info/4096/sipSPISetCommonTimer: Started generic timer type 2 for 240000 millisecs Apr 9 10:10:49.811: //556180/54CD023D81DA/SIP/Info/info/12288/sipSPIDeleteRtpDPSession: Calling delete dp session Apr 9 10:10:49.811: //556180/54CD023D81DA/SIP/Info/verbose/4096/sipSPICallCloseAfterFinalStat: sipSPICallCloseAfterFinalStat: Apr 9 10:10:49.811: //556180/54CD023D81DA/SIP/Info/info/12288/sipSPIIcpifUpdate: CallState: 4 Playout: 0 DiscTime:205733475 ConnTime 205732742 Apr 9 10:10:49.811: //556180/54CD023D81DA/SIP/Media/sipSPIHandleDestroyRtpSession: stream:7FFDB2049D90 Apr 9 10:10:49.811: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x7FFD9D9341A0) counter, current msg->refCount = 1 Apr 9 10:10:49.811: //556180/54CD023D81DA/SIP/State/sipSPIChangeState: 0x7FFDA8AFBAB8 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE) Apr 9 10:10:49.811: //556180/54CD023D81DA/SIP/Call/sipSPICallInfo: The Call Setup Information is: Call Control Block (CCB) : 0x0x7FFDA8AFBAB8 State of The Call : STATE_DEAD TCP Sockets Used : YES Calling Number : +41797329888 Called Number : +35020002501 Source IP Address (Sig ): 10.50.66.1 Destn SIP Req Addr:Port : 10.1.128.135:5060 Destn SIP Resp Addr:Port : 10.1.128.135:54378 Destination Name : 10.1.128.135 Apr 9 10:10:49.811: //556180/54CD023D81DA/SIP/Call/sipSPIMediaCallInfo: Number of Media Streams: 1 Media Stream : 1 Negotiated Codec : T38Fax Negotiated Codec Bytes : 20 Nego. Codec payload : 255 (tx), 255 (rx) Negotiated Dtmf-relay : 0 Dtmf-relay Payload : 0 (tx), 0 (rx) Source IP Address (Media): 10.50.66.1 Source IP Port (Media): 20240 Destn IP Address (Media): 10.1.100.45 Destn IP Port (Media): 56340 Orig Destn IP Address:Port (Media): [ - ]:0 Apr 9 10:10:49.812: //556180/54CD023D81DA/SIP/Call/sipSPICallInfo: Disconnect Cause (CC) : 16 Disconnect Cause (SIP) : 200 Apr 9 10:10:49.812: //556180/54CD023D81DA/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 87C94 Apr 9 10:10:49.812: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[567289] removed. Apr 9 10:10:49.812: //556180/54CD023D81DA/SIP/Info/info/4096/sipSPIStopCommonTimer: Stopping Generic Timer 2 Apr 9 10:10:49.812: //556180/54CD023D81DA/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x7FFDA8AFBAB8 key=54CE3B25-3B0411E8-93DEAD25-DD7BDD2E@10.50.66.1 Apr 9 10:10:49.812: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFD9D9341A0 Apr 9 10:10:49.812: //556180/54CD023D81DA/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Apr 9 10:10:49.812: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x7FFDA0BDA5E8, addr=10.1.128.135, port=5060, local_addr=10.50.66.1, unregistering context=0x7FFDA8AFBAB8 Apr 9 10:10:49.812: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x7FFDA8AFBAB8 from the connection=0x7FFDA0F7BF18 context list Apr 9 10:10:49.812: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x7FFDB3098A28) counter, current msg->refCount = 1 Apr 9 10:10:49.812: //556180/54CD023D81DA/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Apr 9 10:10:49.812: //556180/54CD023D81DA/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer Apr 9 10:10:49.812: //556180/54CD023D81DA/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x7FFDA8AFBAB8 Apr 9 10:10:49.812: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[567289] Apr 9 10:10:49.812: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB3098A28