vg-gib-001#ter mon vg-gib-001# Apr 9 10:11:24.126: //556190/000000000000/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x7FFDA8B9A2E8 Apr 9 10:11:24.126: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[567299] Apr 9 10:11:24.126: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB2D97B60 Apr 9 10:11:26.886: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x7FFDA8B9A2E8) with key=[567300] to table Apr 9 10:11:26.886: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init: Apr 9 10:11:26.886: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init: Apr 9 10:11:26.886: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised.. Apr 9 10:11:26.886: //-1/000000000000/SIP/Info/verbose/4097/ccsip_platform_init_ccb: Initialising rtp session queue Apr 9 10:11:26.886: //556191/000000000000/SIP/State/sipSPIChangeState: 0x7FFDA8B9A2E8 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Apr 9 10:11:26.888: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 37 Apr 9 10:11:26.888: //556191/000000000000/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable: Adding call id 87C9F to table Apr 9 10:11:26.888: //556191/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Apr 9 10:11:26.888: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.50.66.1 for SIP Apr 9 10:11:26.888: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.50.66.1 for SIP Apr 9 10:11:26.888: //556191/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 10.50.66.1 Apr 9 10:11:26.888: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 10.50.66.1 Apr 9 10:11:26.888: //556191/000000000000/SIP/Info/verbose/4096/sipSPIUaddCcbToUACTable: ****Adding to UAC table.0x7FFDA8B9A2E8 6F5A0821-3B0411E8-93E9AD25-DD7BDD2E@10.50.66.1 Apr 9 10:11:26.888: //556191/000000000000/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x7FFDA8B9A2E8 key=6F5A0821-3B0411E8-93E9AD25-DD7BDD2E@10.50.66.1 balance 1 Apr 9 10:11:26.888: //556191/000000000000/SIP/State/sipSPIChangeState: 0x7FFDA8B9A2E8 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_NONE) Apr 9 10:11:26.888: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB3117480 with refCount = 1 Apr 9 10:11:26.888: //556191/000000000000/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 15 event Apr 9 10:11:26.888: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone MEZ_SZ to SIP default timezone = GMT Apr 9 10:11:26.889: //556191/000000000000/SIP/Error/sipSPIAddPrivacyHeader: Orig Container is NULL...should have value except in case of sending OOD Options ping. Apr 9 10:11:26.889: //556191/000000000000/SIP/Error/sipSPIAddAssertedIDHeader: Orig Container is NULL...should have value except in case of sending OOD Options ping. Apr 9 10:11:26.889: //556191/000000000000/SIP/Error/sipSPIAddPreferredIDHeader: Orig Container is NULL...should have value except in case of sending OOD Options ping. Apr 9 10:11:26.889: //556191/000000000000/SIP/Info/info/4096/sipSPISendOptionsRequest: Associated container=0x7FFDB3321918 to Options Apr 9 10:11:26.889: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Apr 9 10:11:26.889: //556191/000000000000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Dial peer configuration, Switch Transport is FALSE Apr 9 10:11:26.889: //556191/000000000000/SIP/Transport/sipSPITransportSendMessage: msg=0x7FFDB3117480, addr=10.50.66.1, port=5060, sentBy_port=0, local_addr=10.50.66.1, is_req=1, transport=2, switch=0, callBack=0x7FFE0B237DB0 Apr 9 10:11:26.889: //556191/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:26.889: //556191/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:26.889: //556191/000000000000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 9 10:11:26.889: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.50.66.1, rport:5060 with laddr:10.50.66.1 Apr 9 10:11:26.889: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x7FFDA8B9A2E8 with connection=0x7FFDA0F7B1A8 context list Apr 9 10:11:26.889: //556191/000000000000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x7FFDB3117480 Apr 9 10:11:26.889: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x7FFDB3117480, addr=10.50.66.1, port=5060, local_addr=10.50.66.1, connId=7 vrfid=0 for TCP Apr 9 10:11:26.889: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_tcp_queue_event: Event type: send msg, connid: 7, fd: 5 Apr 9 10:11:26.889: //556191/000000000000/SIP/Msg/ccsipDisplayMsg: Sent: OPTIONS sip:10.50.66.1:5060 SIP/2.0 Via: SIP/2.0/TCP 10.50.66.1:5060;branch=z9hG4bK56C847A5 From: ;tag=7AA27F82-1B29 To: Date: Mon, 09 Apr 2018 08:11:26 GMT Call-ID: 6F5A0821-3B0411E8-93E9AD25-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:11:26.889: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB3117480 Apr 9 10:11:26.890: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 6 to index 8 Apr 9 10:11:26.890: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB3117480 with refCount = 1 Apr 9 10:11:26.890: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB2D97B60 with refCount = 1 Apr 9 10:11:26.890: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB3117480 Apr 9 10:11:26.890: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Apr 9 10:11:26.890: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Apr 9 10:11:26.890: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x7FFDA0BDA5E8, addr=10.50.66.1, port=22499, local_addr=10.50.66.1, connid=8, transport=TCP Apr 9 10:11:26.890: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 22499 connId 8 Apr 9 10:11:26.890: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: OPTIONS sip:10.50.66.1:5060 SIP/2.0 Via: SIP/2.0/TCP 10.50.66.1:5060;branch=z9hG4bK56C847A5 From: ;tag=7AA27F82-1B29 To: Date: Mon, 09 Apr 2018 08:11:26 GMT Call-ID: 6F5A0821-3B0411E8-93E9AD25-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:11:26.890: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Apr 9 10:11:26.890: //556191/000000000000/SIP/Info/info/4096/sipSPICheckFromToRequest: Trying with child CCB 0x0 index 0 curr_child 0 Apr 9 10:11:26.890: //556191/000000000000/SIP/Error/sipSPICheckFromToRequest: Failed FROM/TO Request check - IGNORE IF HAIRPIN CALL old_from: ;tag=7AA27F82-1B29 old_to: new_from: ;tag=7AA27F82-1B29 new_to: Apr 9 10:11:26.890: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x7FFDA8AFBAB8) with key=[567301] to table Apr 9 10:11:26.891: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init: Apr 9 10:11:26.891: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init: Apr 9 10:11:26.891: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised.. Apr 9 10:11:26.891: //-1/000000000000/SIP/Info/verbose/4097/ccsip_platform_init_ccb: Initialising rtp session queue Apr 9 10:11:26.891: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.50.66.1,Port 22499, Transport 2, SentBy Port 5060vrfid 0 Apr 9 10:11:26.891: //-1/000000000000/SIP/Info/verbose/4608/sipSPISipIncomingMsg: copy the natted transport info to ccb natted dest: 10.50.66.1:22499,natted src: 10.50.66.1:5060, natted transport: 2 Apr 9 10:11:26.891: //-1/000000000000/SIP/Info/info/1024/sipSPISipIncomingMsg: sip via host 10.50.66.1 Apr 9 10:11:26.891: //-1/000000000000/SIP/Info/info/9216/sipSPISipIncomingMsg: sip nat auto detect 0 Apr 9 10:11:26.891: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Apr 9 10:11:26.891: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.50.66.1 for SIP Apr 9 10:11:26.891: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.50.66.1 for SIP Apr 9 10:11:26.891: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 10.50.66.1 Apr 9 10:11:26.891: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 10.50.66.1 Apr 9 10:11:26.891: //-1/6F5A7D8B93EA/SIP/State/sipSPIChangeState: 0x7FFDA8AFBAB8 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Apr 9 10:11:26.891: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.50.66.1,Port 22499, Transport 2, SentBy Port 5060vrfid 0 Apr 9 10:11:26.891: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone MEZ_SZ to SIP default timezone = GMT Apr 9 10:11:26.891: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.50.66.1,Port 22499, Transport 2, SentBy Port 5060vrfid 0 Apr 9 10:11:26.891: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x7FFDB2D97B60) counter, current msg->refCount = 2 Apr 9 10:11:26.891: //-1/xxxxxxxxxxxx/SIP/Error/httpish_msg_free: Freeing NULL pointer! Apr 9 10:11:26.891: //556192/6F5A7D8B93EA/SIP/Info/verbose/1024/sipSPIGetViaHostInURLFormat: VIA URL:sip:10.50.66.1:5060, Host:10.50.66.1 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/verbose/67584/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: : Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Error/sipSPIGetPeerByCalledPartyId: input arg error Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/critical/10240/sipSPIGetCallConfig: No match found for P-Called-Party-ID Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Error/sipSPIUpdateCallInfo: input argument error Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/verbose/1024/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/verbose/2048/sipSPIGetCallConfig: Media Antitrombone disabled Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/8192/sipSPISetMediaFlowMode: Storing the configured mode as FLOW-THROUGH Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/2304/sipSPISetMediaFlowMode: xcoder high-density disabled Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/8192/sipSPISetMediaFlowMode: Flow Mode set to FLOW_THROUGH Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/10240/sipSPIGetCallConfig: Non dial peer leg - using RTP Supported Codecs Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 18 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 0 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 8 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 9 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 4 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 2 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 15 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 3 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/critical/32768/ccsip_ipip_media_forking_update_preferred_codec: MF: Not a Forked SIP leg.. Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/verbose/12288/sipSPIGetModemInfoPerCall: peer_callID=0 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/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:11:26.892: //556192/6F5A7D8B93EA/SIP/Error/ccsip_ipip_media_forking_anchor_leg_config: MF: Dial-peer is absent.. Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/36864/sipSPIMFChangeState: MF: Prev state = 0 & New state = -1 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/32768/ccsip_ipip_media_forking_anchor_leg_reset: MF: Anchor leg config reset done... Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Error/ccsip_ipip_media_forking_intra_frame_request_config: MF:video profile Dial-peer is absent.. Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/verbose/8192/sipSPICheckFAAnatAssymetricOrDO2EO: Not a SIP-SIP call or not in FA mode Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/2049/populate_vcc_data: Non dial peer leg - using RTP Supported Codecs Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 18 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 0 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 8 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 9 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 4 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 2 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 15 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 3 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/notify/8192/sipSPISetOverlapConfiguration: Overlap signaling: FALSE: Endpt: SIP Trunk Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/verbose/10240/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/verbose/2048/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:26.892: //556192/6F5A7D8B93EA/SIP/Info/notify/10240/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled Apr 9 10:11:26.893: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x7FFDB2D97B60) counter, current msg->refCount = 1 Apr 9 10:11:26.893: //556192/6F5A7D8B93EA/SIP/Info/notify/6/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Apr 9 10:11:26.893: //556192/6F5A7D8B93EA/SIP/Info/verbose/513/resolve_media_ip_address_to_bind: peer_tag=0 Apr 9 10:11:26.893: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_media_ip_address_to_bind: VRF id = 0 Apr 9 10:11:26.893: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.50.66.1 for SIP Apr 9 10:11:26.893: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.50.66.1 for SIP Apr 9 10:11:26.893: //556192/6F5A7D8B93EA/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.50.66.1 Apr 9 10:11:26.893: //556192/6F5A7D8B93EA/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Apr 9 10:11:26.893: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.50.66.1 for SIP Apr 9 10:11:26.893: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.50.66.1 for SIP Apr 9 10:11:26.893: //556192/6F5A7D8B93EA/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 10.50.66.1 Apr 9 10:11:26.893: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 10.50.66.1 Apr 9 10:11:26.893: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_OPTIONS_RESP Apr 9 10:11:26.893: //556192/6F5A7D8B93EA/SIP/Info/info/4096/sact_idle_new_message_options: ccsip_api_options_ind returned: SIP_SUCCESS Apr 9 10:11:26.893: //556192/6F5A7D8B93EA/SIP/State/sipSPIChangeState: 0x7FFDA8AFBAB8 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_NONE) Apr 9 10:11:26.893: //556192/6F5A7D8B93EA/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x7FFDA8AFBAB8 key=6F5A0821-3B0411E8-93E9AD25-DD7BDD2E@10.50.66.1 balance 1 Apr 9 10:11:26.893: //556192/6F5A7D8B93EA/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable: Adding call id 87CA0 to table Apr 9 10:11:26.893: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 38 Apr 9 10:11:26.893: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB3117480 with refCount = 1 Apr 9 10:11:26.893: //556192/6F5A7D8B93EA/SIP/Info/info/4096/sipSPISendOptionsResponse: Associated container=0x7FFDB331DD60 to Options Response Apr 9 10:11:26.894: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 364 Apr 9 10:11:26.894: //556192/6F5A7D8B93EA/SIP/Transport/sipSPITransportSendMessage: msg=0x7FFDB3117480, addr=10.50.66.1, port=22499, sentBy_port=5060, local_addr=10.50.66.1, is_req=0, transport=2, switch=0, callBack=0x7FFE0B237E00 Apr 9 10:11:26.894: //556192/6F5A7D8B93EA/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:26.894: //556192/6F5A7D8B93EA/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:26.894: //556192/6F5A7D8B93EA/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 9 10:11:26.894: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x7FFDB3117480, addr=10.50.66.1, port=22499, local_addr=10.50.66.1, connId=8 vrfid=0 for TCP Apr 9 10:11:26.894: //556192/6F5A7D8B93EA/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 87CA0 Apr 9 10:11:26.894: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[567301] removed. Apr 9 10:11:26.894: //556192/6F5A7D8B93EA/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x7FFDA8AFBAB8 key=6F5A0821-3B0411E8-93E9AD25-DD7BDD2E@10.50.66.1 Apr 9 10:11:26.894: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB2D97B60 Apr 9 10:11:26.894: //556192/6F5A7D8B93EA/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Apr 9 10:11:26.894: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x7FFDA0BDA5E8, addr=10.50.66.1, port=22499, local_addr=10.50.66.1, unregistering context=0x7FFDA8AFBAB8 Apr 9 10:11:26.894: //556192/6F5A7D8B93EA/SIP/Transport/sipSPITransportContextCleanup: Could not purge context gcb=0x7FFDA8AFBAB8 from the connection; gcb might be locked Apr 9 10:11:26.894: //556192/6F5A7D8B93EA/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Apr 9 10:11:26.894: //556192/6F5A7D8B93EA/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer Apr 9 10:11:26.894: //556192/6F5A7D8B93EA/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x7FFDA8AFBAB8 Apr 9 10:11:26.894: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[567301] Apr 9 10:11:26.894: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPITransportSendMessage: gcb has cleanedup, Done with send operations for this context Apr 9 10:11:26.894: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[567301] Apr 9 10:11:26.895: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_tcp_queue_event: Event type: send msg, connid: 8, fd: 6 Apr 9 10:11:26.896: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 200 OK Via: SIP/2.0/TCP 10.50.66.1:5060;branch=z9hG4bK56C847A5 From: ;tag=7AA27F82-1B29 To: ;tag=7AA27F84-129A Date: Mon, 09 Apr 2018 08:11:26 GMT Call-ID: 6F5A0821-3B0411E8-93E9AD25-DD7BDD2E@10.50.66.1 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: 364 v=0 o=CiscoSystemsSIP-GW-UserAgent 8991 878 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:11:26.896: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB3117480 Apr 9 10:11:26.896: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 5 to index 7 Apr 9 10:11:26.896: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB3117480 with refCount = 1 Apr 9 10:11:26.896: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB2D97B60 with refCount = 1 Apr 9 10:11:26.896: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB3117480 Apr 9 10:11:26.896: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Apr 9 10:11:26.896: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x7FFDA0BDA5E8 Apr 9 10:11:26.896: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x7FFDA0BDA5E8, addr=10.50.66.1, port=5060, local_addr=10.50.66.1, connid=7, transport=TCP Apr 9 10:11:26.896: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 5060 connId 7 Apr 9 10:11:26.896: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Apr 9 10:11:26.896: //556191/000000000000/SIP/Info/info/1024/sipSPIMatchRespToReqTran: removing unneeded z9hG4bK56C847A5 from via branch list Apr 9 10:11:26.897: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x7FFDB2D97B60) counter, current msg->refCount = 2 Apr 9 10:11:26.897: //556191/000000000000/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 200 OK Via: SIP/2.0/TCP 10.50.66.1:5060;branch=z9hG4bK56C847A5 From: ;tag=7AA27F82-1B29 To: ;tag=7AA27F84-129A Date: Mon, 09 Apr 2018 08:11:26 GMT Call-ID: 6F5A0821-3B0411E8-93E9AD25-DD7BDD2E@10.50.66.1 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: 364 v=0 o=CiscoSystemsSIP-GW-UserAgent 8991 878 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:11:26.897: //556191/000000000000/SIP/Info/verbose/1024/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX Apr 9 10:11:26.897: //556191/000000000000/SIP/Info/info/4096/sipSPIHandle_ccsip_api_options_result: Optionsping feature disabled SIP_ADDR_INVALID = FALSE, Response_code = 200, Source = External, PingStatus NOT SAVED in Stack. Apr 9 10:11:26.897: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x7FFDB2D97B60) counter, current msg->refCount = 1 Apr 9 10:11:26.897: //556191/000000000000/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 87C9F Apr 9 10:11:26.897: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[567300] removed. Apr 9 10:11:26.897: //556191/000000000000/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x7FFDA8B9A2E8 key=6F5A0821-3B0411E8-93E9AD25-DD7BDD2E@10.50.66.1 Apr 9 10:11:26.897: //556191/000000000000/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Apr 9 10:11:26.897: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x7FFDA0BDA5E8, addr=10.50.66.1, port=5060, local_addr=10.50.66.1, unregistering context=0x7FFDA8B9A2E8 Apr 9 10:11:26.897: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x7FFDA8B9A2E8 from the connection=0x7FFDA0F7B1A8 context list Apr 9 10:11:26.897: //556191/000000000000/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Apr 9 10:11:26.897: //556191/000000000000/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer Apr 9 10:11:26.897: //556191/000000000000/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x7FFDA8B9A2E8 Apr 9 10:11:26.897: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[567300] Apr 9 10:11:26.897: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB2D97B60 Apr 9 10:11:27.314: ISDN Se0/1/0:15 Q931: RX <- SETUP pd = 8 callref = 0x0001 Sending Complete Bearer Capability i = 0x9090A3 Standard = CCITT Transfer Capability = 3.1kHz Audio 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, '02523' Plan:ISDN, Type:Subscriber(local) Apr 9 10:11:27.315: ISDN Se0/1/0:15 Q931: Received SETUP callref = 0x8001 callID = 0x020D switch = primary-net5 interface = User Apr 9 10:11:27.318: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x7FFDA8B9A2E8) with key=[567302] to table Apr 9 10:11:27.318: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init: Apr 9 10:11:27.318: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init: Apr 9 10:11:27.318: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised.. Apr 9 10:11:27.318: //-1/000000000000/SIP/Info/verbose/4097/ccsip_platform_init_ccb: Initialising rtp session queue Apr 9 10:11:27.318: //556194/000000000000/SIP/State/sipSPIChangeState: 0x7FFDA8B9A2E8 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Apr 9 10:11:27.318: //556194/000000000000/SIP/Info/critical/32768/ccsip_ipip_media_forking_read_from_TDContainer: MF: Unable to read data from TD Container.. Apr 9 10:11:27.318: //556194/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:11:27.318: //556194/000000000000/SIP/Info/verbose/4096/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 1, Event Id: EV_UNDEFINED Apr 9 10:11:27.318: //556194/000000000000/SIP/Info/verbose/4096/ccsip_iwf_map_ccapi_event_to_iwf_event: IWF Event: E_SIP_IWF_EV_SET_MODE Apr 9 10:11:27.318: //556194/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:11:27.318: //556194/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Apr 9 10:11:27.318: //556194/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev: Apr 9 10:11:27.318: //556194/000000000000/SIP/Info/info/4096/is_mode_sip_sip_md_snr: Apr 9 10:11:27.318: //556194/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev: Apr 9 10:11:27.318: //556194/000000000000/SIP/Info/info/4096/is_mode_sip_sip_ed_snr: Apr 9 10:11:27.318: //556194/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev: Apr 9 10:11:27.318: //556194/000000000000/SIP/Info/info/4096/is_mode_sip_sip_md: Apr 9 10:11:27.318: //556194/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev: Apr 9 10:11:27.318: //556194/000000000000/SIP/Info/info/4096/is_mode_sip_sip_ed: Apr 9 10:11:27.318: //556194/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev: Apr 9 10:11:27.318: //556194/000000000000/SIP/Info/info/4096/is_mode_sip_h32x_in_set_mode: Apr 9 10:11:27.318: //556194/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev: Apr 9 10:11:27.318: //556194/000000000000/SIP/Info/info/4096/is_mode_sip_h323_in_set_mode: Apr 9 10:11:27.318: //556194/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev: Apr 9 10:11:27.318: //556194/000000000000/SIP/Info/info/4096/is_mode_sip_sccp_in_set_mode: Apr 9 10:11:27.319: //556194/000000000000/SIP/Info/info/4096/ccsip_get_int_type_frm_set_mode_ev: Apr 9 10:11:27.319: //556194/000000000000/SIP/Info/info/4096/is_mode_sip_sccp_in_set_mode: Apr 9 10:11:27.319: //556194/000000000000/SIP/Info/info/8192/sip_iwf_def_set_mode_hdlr: Setting SPI mode to SIP-TDM Apr 9 10:11:27.319: //556194/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_default_early_dialog_container Apr 9 10:11:27.319: //556194/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:CNFSM_NO_STATE_CHANGE Apr 9 10:11:27.319: //556194/000000000000/SIP/Info/info/4096/ccsip_iwf_handle_peer_event: Return value: SIP_IWF_SUCCESS Apr 9 10:11:27.319: //556194/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:11:27.319: //556194/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:11:27.319: //556194/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:11:27.319: //556194/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Apr 9 10:11:27.319: //556194/000000000000/SIP/Info/info/4096/is_fa2ft_md_flow_mode_transition: Apr 9 10:11:27.319: //556194/000000000000/SIP/Info/info/4096/is_fa2ft_flow_mode_transition: Apr 9 10:11:27.319: //556194/000000000000/SIP/Info/info/4096/ccsip_get_flow_mode_frm_set_flow_mode_ev: Apr 9 10:11:27.319: //556194/000000000000/SIP/Info/info/4096/is_fa2ft_flow_mode_transition: Apr 9 10:11:27.319: //556194/000000000000/SIP/Info/info/4096/ccsip_get_flow_mode_frm_set_flow_mode_ev: Apr 9 10:11:27.319: //556194/000000000000/SIP/Info/verbose/4096/ccsip_iwf_process_event: IWF - cnfsm ret 2 Apr 9 10:11:27.319: //556194/000000000000/SIP/Info/info/4096/ccsip_iwf_handle_peer_event: Return value: SIP_IWF_SUCCESS Apr 9 10:11:27.319: //556194/000000000000/SIP/Info/info/4096/ccsip_call_setup_request: Before processing SETUP REQccb->pld.flags_ipip = 200 Apr 9 10:11:27.319: //556194/000000000000/SIP/Info/info/4096/ccsip_call_setup_request: After processing SETUP REQccb->pld.flags_ipip = 200 Apr 9 10:11:27.319: //556194/6F9B310C81DB/SIP/Info/verbose/4096/ccsip_call_setup_request: Number Translation Set For Called-Number Apr 9 10:11:27.319: //556194/6F9B310C81DB/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:27.319: //556194/6F9B310C81DB/SIP/Error/sipSPIGetCallSessionTarget: No session target configured Apr 9 10:11:27.319: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIProcessTargetInfoDestList: Processing target destination list Apr 9 10:11:27.319: //556194/6F9B310C81DB/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable: Adding call id 87CA2 to table Apr 9 10:11:27.319: //556194/6F9B310C81DB/SIP/Info/notify/131072/ccsip_call_setup_request: Incrementing call counter to [1] in dial-peer [500] Apr 9 10:11:27.319: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_SETUP Apr 9 10:11:27.319: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 2 Apr 9 10:11:27.319: //556194/6F9B310C81DB/SIP/Info/info/2049/sipSPIGetCallConfig: preferred_codec set[0] type :No Codec bytes: 0 Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/verbose/2048/sipSPI_ipip_store_config_info: Setting mid_call_config_info = 0x0 for callid = 556194 Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/info/8192/sipSPIGetCallConfig: Media forking disabled Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/info/32768/sipSPIGetCallConfig: Media Antitrombone disabled Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/notify/131072/sipSPICanSetFallbackFlag: Local Fallback is not active Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/info/8192/sipSPIGetCallConfig: VRF id = 0 Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/info/8192/sipSPISetMediaFlowMode: Storing the configured mode as FLOW-THROUGH Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/info/2304/sipSPISetMediaFlowMode: xcoder high-density disabled Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/info/8192/sipSPISetMediaFlowMode: Flow Mode set to FLOW_THROUGH Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/info/1/sipSPIGetCallConfig: Using Voice Class Codec, tag = 10 and offer-all is = FALSE Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Media/sipSPICopyStunConfigFromPeerToCCB: Firewall traversal is not enabled Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/verbose/12288/sipSPIGetModemInfoPerCall: peer_callID=556193 Apr 9 10:11:27.320: //556194/6F9B310C81DB/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:11:27.320: //556194/6F9B310C81DB/SIP/Info/critical/32768/ccsip_ipip_media_forking_update_preferred_codec: MF: Not a Forked SIP leg.. Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/info/8704/sipSPIGetCallConfig: Incoming: No defer BYE for last call stats Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/verbose/1/ccsip_set_srtp_config: No Srtp configure for this leg. Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/info/8192/sipSPIGetCallConfig: Media forking disabled Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/info/34816/ccsip_ipip_media_forking_anchor_leg_config: MF: en_p->encap_s.voIP.voipPeerCfgMediaClass = 0 Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/info/34816/ccsip_ipip_media_forking_anchor_leg_config: MF: Dial-peer has no media class recorder. Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/info/36864/sipSPIMFChangeState: MF: Prev state = 0 & New state = -1 Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/info/32768/ccsip_ipip_media_forking_anchor_leg_reset: MF: Anchor leg config reset done... Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/info/32768/ccsip_ipip_media_forking_intra_frame_request_config: MF: FIR en_p->encap_s.voIP.voipPeerCfgMediaClass = 0 Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/info/32768/ccsip_ipip_media_forking_get_forked_leg_config: MF: This leg is not forked call leg. Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/critical/11264/ccsipInitDSCPPolicyInfo: No DSCP Profile configured, No RPH 2 DSCP Mapping and DSCP policing Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/verbose/8192/sipSPIGetCallConfig: Initilise the DSCP policy Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/verbose/8192/sipSPICheckFAAnatAssymetricOrDO2EO: Not a SIP-SIP call or not in FA mode Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/notify/2049/populate_vcc_data: Using Voice Class Codec, tag = 10 and offer-all is = FALSE Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/notify/8192/sipSPISetOverlapConfiguration: Overlap signaling: FALSE: Endpt: SIP Trunk Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/verbose/10240/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0 Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/verbose/2048/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0 Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/notify/10240/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/info/1/preprocessSetup: This is a not a SIGO Call -, could be DM call Apr 9 10:11:27.320: //556194/6F9B310C81DB/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:11:27.320: //556194/6F9B310C81DB/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/verbose/4096/ccsip_iwf_process_event: IWF - cnfsm ret 2 Apr 9 10:11:27.320: //556194/6F9B310C81DB/SIP/Info/notify/4096/preprocessSetup: SIP-TDM or TCL/VXML app case Apr 9 10:11:27.321: //556194/6F9B310C81DB/SIP/Info/notify/6/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Apr 9 10:11:27.321: //556194/6F9B310C81DB/SIP/Info/verbose/513/resolve_media_ip_address_to_bind: peer_tag=500 Apr 9 10:11:27.321: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_media_ip_address_to_bind: VRF id = 0 Apr 9 10:11:27.321: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.50.66.1 for SIP Apr 9 10:11:27.321: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.50.66.1 for SIP Apr 9 10:11:27.321: //556194/6F9B310C81DB/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.50.66.1 Apr 9 10:11:27.321: //556194/6F9B310C81DB/SIP/Info/critical/1/sipSPIOutgoingCallSDP: Failure in creating outbound streams SIP: (556194) Group (a= group line) attribute, level 65535 instance 1 not found. Apr 9 10:11:27.321: //556194/6F9B310C81DB/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Apr 9 10:11:27.321: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.50.66.1 for SIP Apr 9 10:11:27.321: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.50.66.1 for SIP Apr 9 10:11:27.321: //556194/6F9B310C81DB/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 10.50.66.1 Apr 9 10:11:27.321: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 10.50.66.1 Apr 9 10:11:27.321: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIReserveRtpPort: reserved port 20242 for stream 1 Apr 9 10:11:27.321: //556194/6F9B310C81DB/SIP/Info/info/1/sipSPIDoBearerCapToCodecMapping: Bearer capability to Codec Mapping: DISABLED Apr 9 10:11:27.321: //556194/6F9B310C81DB/SIP/Media/sipSPIAddSDPMediaPayload: Preferred method of dtmf relay is: 6, with payload: 101 Apr 9 10:11:27.321: //556194/6F9B310C81DB/SIP/Info/info/131074/sipSPIBwCacCalcMaxAudioBandwidth: calculating max bw from preffered codecs (local offer) SIP: (556194) Group (a= group line) attribute, level 65535 instance 1 not found. Apr 9 10:11:27.321: //556194/6F9B310C81DB/SIP/Info/info/131074/sipSPIBwCacCalcMaxAudioBandwidth: max bw (excluding pak overhead) from preffered codecs: codec g711ulaw bw 64000 index 0 Apr 9 10:11:27.321: //556194/6F9B310C81DB/SIP/Info/critical/2/sipSPIBwCacCalcMaxAudioBandwidth: audio caps channel idx not found !!!! Apr 9 10:11:27.321: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20 Apr 9 10:11:27.321: //556194/6F9B310C81DB/SIP/Info/info/131074/sipSPIBwCacCalcMaxAudioBandwidth: max bw (including pak overhead) from preffered codecs: codec g711ulaw bw 80000 Apr 9 10:11:27.321: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20 Apr 9 10:11:27.321: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/convert_codec_bytes_to_ptime: Values :Codec: g711alaw codecbytes :160, ptime: 20 Apr 9 10:11:27.321: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/convert_codec_bytes_to_ptime: Values :Codec: g729r8 codecbytes :20, ptime: 20 Apr 9 10:11:27.321: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/sipSPISetMediaDirectionForStream: Setting Media direction SENDRECV for stream 1 Apr 9 10:11:27.321: //556194/6F9B310C81DB/SIP/Info/notify/8193/sip_generate_sdp_xcaps_list: Modem Relay and T38 disabled. X-cap not needed Apr 9 10:11:27.321: //556194/6F9B310C81DB/SIP/Info/info/1/sipSPIOutgoingCallSDP: Creating recv-only stream for outbound call Apr 9 10:11:27.321: //556194/6F9B310C81DB/SIP/Media/sipSPIProcessRtpSessions: Processing stream state = STREAM_IDLE Apr 9 10:11:27.321: //556194/6F9B310C81DB/SIP/Media/sipSPIProcessRtpSessions: No active streams. Apr 9 10:11:27.321: //556194/6F9B310C81DB/SIP/Info/notify/4096/sip_gw_pre_setup_update_stream_media_direction: peer_callID = 556193 Apr 9 10:11:27.321: //556194/6F9B310C81DB/SIP/Info/critical/4097/sip_gw_pre_setup_update_stream_media_direction: peer_channels/stream is NULL Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/verbose/1/sip_gw_pre_setup_add_sdp_container: SDP container added Apr 9 10:11:27.322: //556194/6F9B310C81DB/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:11:27.322: //556194/6F9B310C81DB/SIP/Info/info/131072/sipSPIBwCacUpdateInterfaceBw: bwcac acquiring interface Loopback0 bw 80 Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/info/131072/sipSPIBwCacUpdateAccountedBw: bwcac update accounted bw (initial offer) accounted bw set to 80000 Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/info/133120/sipSPIBwCacIsDialPeerBwAvailable: bwcac NOP dial-peer bw available tag 500 Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/notify/1/sipSPIBwCacIsInterfaceBwAvailable: bwcac interface bw threshold not configured Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/info/131072/sipSPIBwCacVerifyBwThreshold: bwcac verify bw threshold, bw available allow call total bw 80000 bps Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/critical/8192/sipSPIValidateGtd: Signal Forward disabled Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/critical/8192/sipSPIValidateTunnelData: RawMsg/QSIG Tunneling Not Enabled Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/critical/10240/sipSPIAddMLPPServicesInfo: No MLP Info available on incoming leg Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/info/3072/sipSPIPreprocessUriFormat: Url cfg for 1: 2,phone-ctxt=FALSE Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/info/9216/sipSPIAddCiscoGcid: Gcid value not set - not adding header. Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/verbose/8192/sipSPIAddPrivacyandIdentityInfo: Removing "id" value from Privacy Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/critical/2048/sipSPICompareHistoryInfoWithMatchedDialpeer: call-route history-info CLI not enabled Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/critical/1024/sipSPI_ipip_set_history_info_header: No HI header recvd from container Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Apr 9 10:11:27.322: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.50.66.1 for SIP Apr 9 10:11:27.322: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.50.66.1 for SIP Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 10.50.66.1 Apr 9 10:11:27.322: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 10.50.66.1 Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/info/131072/sipSPIRscmsmAvail: Value returned by check is = 0 Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Apr 9 10:11:27.322: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.50.66.1 for SIP Apr 9 10:11:27.322: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.50.66.1 for SIP Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 10.50.66.1 Apr 9 10:11:27.322: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 10.50.66.1 Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/verbose/4096/sipSPIUaddCcbToUACTable: ****Adding to UAC table.0x7FFDA8B9A2E8 6F9C429F-3B0411E8-93F0AD25-DD7BDD2E@10.50.66.1 Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x7FFDA8B9A2E8 key=6F9C429F-3B0411E8-93F0AD25-DD7BDD2E@10.50.66.1 balance 1 Apr 9 10:11:27.322: //556194/6F9B310C81DB/SIP/Info/verbose/12288/sipSPIUsetBillingProfile: sipCallId for billing records = 6F9C429F-3B0411E8-93F0AD25-DD7BDD2E@10.50.66.1 Apr 9 10:11:27.322: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.1.128.135,Port 5060, Transport 2, SentBy Port 5060vrfid 0 Apr 9 10:11:27.322: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone MEZ_SZ to SIP default timezone = GMT Apr 9 10:11:27.322: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFD9D9341A0 with refCount = 1 Apr 9 10:11:27.323: //556194/6F9B310C81DB/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_REQ Apr 9 10:11:27.323: //556194/6F9B310C81DB/SIP/Event/Session-Timer/sipSTSLMain: dir:1, method:102, resp_code:0, container:7FFDB332B3E0 Apr 9 10:11:27.323: //556194/6F9B310C81DB/SIP/Info/info/8192/Session-Timer/sipSTSLSRReqSend: Session timer is not required Apr 9 10:11:27.323: //556194/6F9B310C81DB/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:11:27.323: //556194/6F9B310C81DB/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 0 event Apr 9 10:11:27.323: //556194/6F9B310C81DB/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Apr 9 10:11:27.323: //556194/6F9B310C81DB/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Apr 9 10:11:27.323: //556194/6F9B310C81DB/SIP/Info/info/4096/ccsip_offer_ans_handle_sent_sdp: Apr 9 10:11:27.323: //556194/6F9B310C81DB/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:11:27.323: //556194/6F9B310C81DB/SIP/Info/info/4096/ccsip_offer_ans_is_invite_offer_valid: TRUE Apr 9 10:11:27.323: //556194/6F9B310C81DB/SIP/Info/info/4096/ccsip_offer_ans_common_offer_sent_hdlr: Apr 9 10:11:27.323: //556194/6F9B310C81DB/SIP/Info/info/4096/ccsip_iwf_handle_network_event: Apr 9 10:11:27.323: //556194/6F9B310C81DB/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:11:27.323: //556194/6F9B310C81DB/SIP/Info/info/4096/sip_iwf_def_ed_sent_sdp_offer_hdlr: Apr 9 10:11:27.323: //556194/6F9B310C81DB/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:S_SIP_IWF_SDP_SENT_AWAIT_SDP Apr 9 10:11:27.323: //556194/6F9B310C81DB/SIP/State/ccsip_cnfsm_debugs: OA:next_state:S_SIP_EARLY_DIALOG_OFFER_SENT Apr 9 10:11:27.323: //-1/xxxxxxxxxxxx/SIP/Info/info/2048/sipSPIgetRegistrarHost: registrar host retrieved : 10.50.66.1 Apr 9 10:11:27.323: //556194/6F9B310C81DB/SIP/Info/critical/4096/ccsip_ipip_media_forking_get_forked_recording_data: MF: Not a Forked leg.. Apr 9 10:11:27.323: //556194/6F9B310C81DB/SIP/Info/critical/1024/sipSPICreateRecParticipantHeaders: X-Cisco-Recording-Participant header not added. SIP: (556194) Group (a= group line) attribute, level 65535 instance 1 not found. Apr 9 10:11:27.323: //556194/6F9B310C81DB/SIP/Info/info/34816/sipSPIGetCallExtensionSupported: anat enabled, src_sdp dont have anat Apr 9 10:11:27.323: //556194/6F9B310C81DB/SIP/Info/info/4096/sipSPISendInvite: Associated container=0x7FFDB332B3E0 to Invite Apr 9 10:11:27.323: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 361 Apr 9 10:11:27.323: //556194/6F9B310C81DB/SIP/Transport/sipSPISendInvite: Sending Invite to the transport layer Apr 9 10:11:27.323: //556194/6F9B310C81DB/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Dial peer configuration, Switch Transport is FALSE Apr 9 10:11:27.323: //556194/6F9B310C81DB/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:11:27.324: //556194/6F9B310C81DB/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:27.324: //556194/6F9B310C81DB/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:27.324: //556194/6F9B310C81DB/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 9 10:11:27.324: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.1.128.135, rport:5060 with laddr:10.50.66.1 Apr 9 10:11:27.324: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x7FFDA8B9A2E8 with connection=0x7FFDA0F7BF18 context list Apr 9 10:11:27.324: //556194/6F9B310C81DB/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x7FFD9D9341A0 Apr 9 10:11:27.324: //-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:11:27.324: //556194/6F9B310C81DB/SIP/Info/info/512/sentInviteRequest: Sent Invite in state STATE_IDLE Apr 9 10:11:27.324: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sentInviteRequest: Transaction active. Facilities will be queued. Apr 9 10:11:27.324: //556194/6F9B310C81DB/SIP/State/sipSPIChangeState: 0x7FFDA8B9A2E8 : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_SENT_INVITE, SUBSTATE_NONE) Apr 9 10:11:27.324: //556194/6F9B310C81DB/SIP/Media/sipSPIProcessRtpSessions: Processing stream state = STREAM_ADDING Apr 9 10:11:27.324: //556194/6F9B310C81DB/SIP/Info/verbose/6/sipSPIAddStream: set stream_callid from ccb->ccCallID:0x87CA2, media_type:0 Apr 9 10:11:27.324: //556194/6F9B310C81DB/SIP/Media/sipSPIAddStream: Adding stream 1 of type voice+dtmf (callid 556194) to the VOIP RTP library Apr 9 10:11:27.324: //556194/6F9B310C81DB/SIP/Info/notify/6/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Apr 9 10:11:27.324: //556194/6F9B310C81DB/SIP/Info/verbose/513/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr Apr 9 10:11:27.324: //556194/6F9B310C81DB/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.50.66.1 Apr 9 10:11:27.324: //556194/6F9B310C81DB/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1 Apr 9 10:11:27.324: //556194/6F9B310C81DB/SIP/Info/info/1/sipSPIAssignStreamCallId: Assigning streamid 556194 to stream 1. Old streamid = 556194 Apr 9 10:11:27.324: //556194/6F9B310C81DB/SIP/Info/info/8192/sipSPIUpdateRtcpSession: ccb->flags != LOOPBACK Apr 9 10:11:27.324: //556194/6F9B310C81DB/SIP/Media/sipSPIUpdateRtcpSession: Setting do_rtcp = FALSE 0 Apr 9 10:11:27.324: //556194/6F9B310C81DB/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info laddr = 10.50.66.1, lport = 20242, raddr = 0.0.0.0, rport=0, do_rtcp=FALSE src_callid = 556194, 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:11:27.324: //556194/6F9B310C81DB/SIP/Media/sipSPIUpdateRtcpSession: No rtp session, creating a new one Apr 9 10:11:27.324: //556194/6F9B310C81DB/SIP/Info/verbose/1/sipSPICreateRtpSession: sess: 7FFDA4A8B788 do_rtcp:0 Apr 9 10:11:27.324: //556194/6F9B310C81DB/SIP/Media/sipSPICreateRtpSession: stun is disabled Apr 9 10:11:27.324: //556194/6F9B310C81DB/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:11:27.324: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIUpdateRtcpSession: Voice quality monitoring is not enabled for this RTP session due to sdp passthru enabled Apr 9 10:11:27.324: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIUpdateRtcpSession: VQM: gccb=0x0, gccb->callId=0, ccb->ccCallID=556194 Apr 9 10:11:27.324: //556194/6F9B310C81DB/SIP/Info/notify/2080/sipSPIUpdateRtcpSession: DTMF inb/oob disabled Apr 9 10:11:27.324: //556194/6F9B310C81DB/SIP/State/sipSPIChangeStreamState: Stream (callid = 556194) State changed from (STREAM_ADDING) to (STREAM_ACTIVE) Apr 9 10:11:27.324: //556194/6F9B310C81DB/SIP/Info/info/2/sipSPIUpdateCallEntry: Call 556194 set InfoType to SPEECH Apr 9 10:11:27.325: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_tcp_queue_event: Event type: send msg, connid: 65, fd: 7 Apr 9 10:11:27.325: //556194/6F9B310C81DB/SIP/Msg/ccsipDisplayMsg: Sent: INVITE sip:+35020002523@10.1.128.135 SIP/2.0 Via: SIP/2.0/TCP 10.50.66.1:5060;branch=z9hG4bK56C8518A0 From: ;tag=7AA28134-536 To: Date: Mon, 09 Apr 2018 08:11:27 GMT Call-ID: 6F9C429F-3B0411E8-93F0AD25-DD7BDD2E@10.50.66.1 Supported: 100rel,timer,resource-priority,replaces,sdp-anat Min-SE: 1800 Cisco-Guid: 1872441612-0990122472-2178665494-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: 1523261487 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 9713 3474 IN IP4 10.50.66.1 s=SIP Call c=IN IP4 10.50.66.1 t=0 0 m=audio 20242 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:11:27.325: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFD9D9341A0 Apr 9 10:11:27.325: ISDN Se0/1/0:15 Q931: TX -> CALL_PROC pd = 8 callref = 0x8001 Channel ID i = 0xA98381 Exclusive, Channel 1 Apr 9 10:11:27.382: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 7 to index 65 Apr 9 10:11:27.441: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x7FFDB2D061F8) counter, current msg->refCount = 1 Apr 9 10:11:27.444: ISDN Se0/1/0:15 Q931: TX -> ALERTING pd = 8 callref = 0x8001 Apr 9 10:11:28.535: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 7 to index 65 Apr 9 10:11:28.535: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFD9D9341A0 with refCount = 1 Apr 9 10:11:28.535: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB3098A28 with refCount = 1 Apr 9 10:11:28.535: //-1/xxxxxxxxxxxx/SIP/Info/critical/1024/httpish_msg_process_network_msg: HEADER LINE READ FAILURE DUE TO RS->EOF Apr 9 10:11:28.535: //-1/xxxxxxxxxxxx/SIP/Info/critical/1024/ccsip_process_network_message: process_network_msg: not complete Apr 9 10:11:28.535: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB3098A28 Apr 9 10:11:28.535: //-1/xxxxxxxxxxxx/SIP/Info/critical/4096/sip_tcp_newmsg_to_spi: process_network_msg: not complete Apr 9 10:11:28.535: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFD9D9341A0 Apr 9 10:11:28.536: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 7 to index 65 Apr 9 10:11:28.536: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFD9D9341A0 with refCount = 1 Apr 9 10:11:28.536: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB33E7D50 with refCount = 1 Apr 9 10:11:28.536: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFD9D9341A0 Apr 9 10:11:28.536: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Apr 9 10:11:28.536: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x7FFDA0BDA5E8 Apr 9 10:11:28.536: //-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:11:28.536: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 5060 connId 65 Apr 9 10:11:28.536: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Apr 9 10:11:28.536: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x7FFDB33E7D50) counter, current msg->refCount = 2 Apr 9 10:11:28.536: //556194/6F9B310C81DB/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 200 OK Via: SIP/2.0/TCP 10.50.66.1:5060;branch=z9hG4bK56C8518A0 From: ;tag=7AA28134-536 To: ;tag=20449157~066d7f19-322a-43ba-8eca-ef58947b04ca-62721648 Date: Mon, 09 Apr 2018 08:11:27 GMT Call-ID: 6F9C429F-3B0411E8-93F0AD25-DD7BDD2E@10.50.66.1 CSeq: 101 INVITE Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY Allow-Events: presence, kpml Supported: replaces Server: Cisco-CUCM10.5 Call-Info: ;method="NOTIFY;Event=telephone-event;Duration=500" Supported: X-cisco-srtp-fallback Supported: Geolocation Session-Expires: 14400;refresher=uas Require: timer P-Asserted-Identity: "GIB IT room" Remote-Party-ID: "GIB IT room" ;party=called;screen=yes;privacy=off Contact: Content-Type: application/sdp Content-Length: 246 v=0 o=CiscoSystemsCCM-SIP 20449157 1 IN IP4 10.1.128.135 s=SIP Call c=IN IP4 10.50.80.1 b=TIAS:64000 b=CT:64 b=AS:64 t=0 0 m=audio 21468 RTP/AVP 0 101 a=ptime:20 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 Apr 9 10:11:28.536: //556194/6F9B310C81DB/SIP/Info/verbose/1024/sipSPICheckResponseExt: INVITE response with no RSEQ - disable IS_REL1XX Apr 9 10:11:28.537: //-1/xxxxxxxxxxxx/SIP/Info/critical/4096/sipSPIGetContentGTD: No GTD found in inbound container Apr 9 10:11:28.537: //556194/6F9B310C81DB/SIP/Info/verbose/4096/sipSPIhandle200OKInvite: Transaction active. Facilities will be queued. Apr 9 10:11:28.537: //556194/6F9B310C81DB/SIP/Info/info/4096/sipSPIhandle200OKInvite: *** This ccb is the parent Apr 9 10:11:28.537: //556194/6F9B310C81DB/SIP/Info/info/4096/ccsip_iwf_handle_generic_event: Apr 9 10:11:28.537: //556194/6F9B310C81DB/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_default_early_dialog_container, cur_state:S_SIP_IWF_SDP_SENT_AWAIT_SDP, event:E_SIP_IWF_EV_CALL_BRIDGE Apr 9 10:11:28.537: //556194/6F9B310C81DB/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Apr 9 10:11:28.537: //556194/6F9B310C81DB/SIP/Info/verbose/4096/ccsip_iwf_process_event: IWF - cnfsm ret 2 Apr 9 10:11:28.537: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB2D061F8 Apr 9 10:11:28.537: //556194/6F9B310C81DB/SIP/Info/verbose/1024/sipSPIProcessNotifyCallInfoHeader: Callinfo parsed - Destination url = , duration = 500 Apr 9 10:11:28.537: //556194/6F9B310C81DB/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_RESP Apr 9 10:11:28.537: //556194/6F9B310C81DB/SIP/Event/Session-Timer/sipSTSLMain: dir:2, method:102, resp_code:200, container:7FFDB331FF18 Apr 9 10:11:28.537: //556194/6F9B310C81DB/SIP/Info/info/8192/Session-Timer/sipSTSLExtractSessionExpiresHdr: Session-Expires value: 14400 refresher: uas Apr 9 10:11:28.537: //556194/6F9B310C81DB/SIP/Info/info/8192/Session-Timer/sipSTSLSRRespRcvd: Session expires params received starting the timer based on the refresher Apr 9 10:11:28.537: //556194/6F9B310C81DB/SIP/Info/info/8192/Session-Timer/sipSTSLStartSessionTimer: Started Session Expiry Timer with duration:14368000 Apr 9 10:11:28.537: //556194/6F9B310C81DB/SIP/Info/info/8192/Session-Timer/sipSTSLMain: SE: 14400;refresher:uas peer refresher:none, flags:0, posted event:E_STSL_INVALID_PEER_EVENT, reason:4 Configured SE:1800, Configured Min-SE:1800 Apr 9 10:11:28.537: //556194/6F9B310C81DB/SIP/Info/critical/1024/sipSPIProcessHistoryInfoHeader: No HI headers recvd from app container Apr 9 10:11:28.537: //556194/6F9B310C81DB/SIP/Info/verbose/1/sipSPICompareRespMediaInfo: No Comparsion needed as 18x response SDP is either absent or ignored Apr 9 10:11:28.537: //556194/6F9B310C81DB/SIP/Info/verbose/1/sipSPIDoMediaNegotiation: Number of m-lines = 1 Apr 9 10:11:28.537: //556194/6F9B310C81DB/SIP/Info/verbose/1/sipSPIValidateConnectionAddress: Dest port = 21468 SIP: Attribute mid, level 1 instance 1 not found. Apr 9 10:11:28.537: //556194/6F9B310C81DB/SIP/Info/notify/6/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Apr 9 10:11:28.537: //556194/6F9B310C81DB/SIP/Info/verbose/513/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr Apr 9 10:11:28.537: //556194/6F9B310C81DB/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.50.66.1 Apr 9 10:11:28.537: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/sipSPICheckDynPayloadUse: Dynamic payload(101) reserved for codec No Codec Apr 9 10:11:28.537: //-1/xxxxxxxxxxxx/SIP/Info/info/1/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 96 Apr 9 10:11:28.537: //-1/xxxxxxxxxxxx/SIP/Info/critical/1/sipSPICheckDynPayloadUse: Dynamic payload(101) could not be reserved as its in use by other codec Apr 9 10:11:28.538: //-1/xxxxxxxxxxxx/SIP/Info/critical/1/sipSPIUpdateDynamicPT: Requested payload-Type (101) is reserved by another application Apr 9 10:11:28.538: //-1/xxxxxxxxxxxx/SIP/Info/info/1/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 98 Apr 9 10:11:28.538: //-1/xxxxxxxxxxxx/SIP/Info/info/1/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 101 Apr 9 10:11:28.538: //-1/xxxxxxxxxxxx/SIP/Info/info/1/sipSPIAllocateFreeDynamicPT: Allocating free Dynamic Payload : 98 for Codec: Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/notify/1/sipSPIDoAudioNegotiation: Codec (g711ulaw) Negotiation Successful on Static Payload for m-line 1 Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/verbose/1/sipSPIDoPtimeNegotiation: One ptime attribute found - value:20 Apr 9 10:11:28.538: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/convert_ptime_to_codec_bytes: Values :Codec: g711ulaw ptime :20, codecbytes: 160 Apr 9 10:11:28.538: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20 Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Media/sipSPIDoPtimeNegotiation: Offered ptime:20, Negotiated ptime:20 Negotiated codec bytes: 160 for codec g711ulaw Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/info/8/sipSPISetFaxFlags: FAX_PASSTHROUGH = 0, END_FAX_PASSTHROUGH = 0 Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/info/1/sipSPIDoDTMFRelayNegotiation: m-line index 1 Apr 9 10:11:28.538: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/sipSPICheckDynPayloadUse: Dynamic payload(101) reserved for codec Apr 9 10:11:28.538: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/sipSPICheckDynPayloadUse: Dynamic payload(101) reserved for codec Apr 9 10:11:28.538: //-1/xxxxxxxxxxxx/SIP/Info/info/1/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 98 Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/notify/1/sipSPIReserveRtpNtePayload: Reserved the payload type 101 for RTP-NTE Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/info/32/sipSPIDoDTMFRelayNegotiation: RTP-NTE DTMF relay option Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/info/1/sipSPIDoDTMFRelayNegotiation: Case of partial named event(NE) match in fmtp list of events. Apr 9 10:11:28.538: //-1/xxxxxxxxxxxx/SIP/Info/info/8209/sip_sdp_get_modem_relay_cap_params: V150 NSE payload = 0, SSE payload = 0, SPRT payload=0 Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/critical/8193/sip_select_modem_relay_params: X-tmr not present in SDP. Disable modem relay Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/info/1/sipSPIGetSDPDirectionAttribute: No direction attribute present or multiple direction attributes that can't be handled for m-line:1 and num-a-lines:0 Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/notify/1/sipSPIDoAudioNegotiation: Codec negotiation successful for media line 1 payload_type=0, codec_bytes=160, codec=g711ulaw, dtmf_relay=rtp-nte stream_type=voice+dtmf (1), dest_ip_address=10.50.80.1, dest_port=21468 Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/State/sipSPIChangeStreamState: Stream (callid = -1) State changed from (STREAM_DEAD) to (STREAM_ADDING) Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Media/sipSPIUpdCallWithSdpInfo: Preferred Codec : g711ulaw, bytes :160 Preferred DTMF relay : rtp-nte Preferred NTE payload : 101 Early Media : No Delayed Media : No Bridge Done : No New Media : No DSP DNLD Reqd : No Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/notify/6/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/verbose/513/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.50.66.1 Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/info/4096/ccsip_offer_ans_handle_rcvd_sdp: Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/State/ccsip_cnfsm_debugs: OA:cur_container:ccsip_offer_ans_main_container, cur_state:S_SIP_EARLY_DIALOG_OFFER_SENT, event:E_SIP_INVITE_RESP_SDP_RCVD Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/info/4096/ccsip_offer_ans_is_incoming_invite_resp_answer_valid: TRUE Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/info/4096/ccsip_offer_ans_common_answer_rcvd_hdlr: Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/info/4096/ccsip_iwf_handle_network_event: Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_default_early_dialog_container, cur_state:S_SIP_IWF_SDP_SENT_AWAIT_SDP, event:E_SIP_IWF_EV_RCVD_SDP Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/info/4096/sip_iwf_def_ed_rcvd_sdp_answer_hdlr: Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/info/131074/sipSPIBwCacCalcNegoAudioBandwidth: max audio bw (including pak overhead) from negotiated stream : codec g711ulaw bw 80000 bps index 1 Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/info/131072/sipSPIBwCacUpdateAccountedBw: bwcac update accounted BW Option 1 flow mode flow-through audio bw 80000 bps video bw 0 bps fax bw 0 bps total bw 80000 bps accounted bw 80000 bps Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/info/131072/sipSPIBwCacUpdateAccountedBw: bwcac update accounted bw (initial answer) no change in accounted bw 80000 Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/Info/info/139264/sipSPIBwCacUpdateInterfaceBw: NOP (no interface change) Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:S_SIP_IWF_SDP_DONE Apr 9 10:11:28.538: //556194/6F9B310C81DB/SIP/State/ccsip_cnfsm_debugs: OA:next_state:S_SIP_EARLY_DIALOG_OFFER_ANSWER_COMPLETE Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/Media/sipSPIUpdCallWithSdpInfo: Stream type : voice+dtmf Media line : 1 State : STREAM_ADDING (2) Stream address type : 1 Callid : 556194 Negotiated Codec : g711ulaw, bytes :160 Nego. Codec payload : 0 (tx), 0 (rx) Negotiated DTMF relay : rtp-nte Negotiated NTE payload : 101 (tx), 101 (rx) Negotiated CN payload : 0 Media Srce Addr/Port : [10.50.66.1]:20242 Media Dest Addr/Port : [10.50.80.1]:21468 Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/Info/verbose/1/sipSPIProcessMediaChanges: sipSPIProcessMediaChanges Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/Info/info/133120/sipSPIBwCacIsDialPeerBwAvailable: bwcac NOP dial-peer bw available tag 500 Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/Info/info/131072/sipSPIBwCacVerifyBwThreshold: bwcac verify bw threshold, bw available allow call total bw 80000 bps Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/Info/info/4096/sipSPIhandle200OKInvite: ccsip_api_call_connect_media returned: SIP_SUCCESS Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/State/sipSPIChangeState: 0x7FFDA8B9A2E8 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING) to (STATE_RECD_PROCEEDING, SUBSTATE_NONE) Apr 9 10:11:28.539: //-1/xxxxxxxxxxxx/SIP/Info/critical/4096/sipSPIGetContentQSIG: No QSIG Body found in inbound container Apr 9 10:11:28.539: //-1/xxxxxxxxxxxx/SIP/Info/critical/4096/sipSPIGetContentQ931: No RawMsg Body found in inbound container Apr 9 10:11:28.539: //-1/xxxxxxxxxxxx/SIP/Info/critical/12288/sipSPICreateNewRawMsg: No Data to form The Raw Message Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/Info/verbose/67584/sipSPIShrlCall: Check peer: 500 for Shared-Line call, callid: 556194 Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/Info/info/8192/sipSPIOptionsPing: Session Timer negotiated, not doing Options Ping Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/Info/info/4096/sipSPIhandle200OKInvite: ccsip_api_call_connected returned: SIP_SUCCESS Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/State/sipSPIChangeState: 0x7FFDA8B9A2E8 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_NONE) to (SIP_STATE_RECD_SUCCESS, SUBSTATE_NONE) Apr 9 10:11:28.539: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB2D061F8 with refCount = 1 Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 1 event Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/Info/info/4096/ccsip_offer_ans_handle_call_active: Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/State/ccsip_cnfsm_debugs: OA:cur_container:ccsip_offer_ans_main_container, cur_state:S_SIP_EARLY_DIALOG_OFFER_ANSWER_COMPLETE, event:E_SIP_DIALOG_ESTD Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/Info/info/4096/ccsip_offer_ans_dialog_established_hdlr: Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/Info/info/4096/ccsip_iwf_handle_generic_event: Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_default_early_dialog_container, cur_state:S_SIP_IWF_SDP_DONE, event:E_SIP_IWF_EV_CALL_ACTIVE Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/Info/info/4096/is_mode_sip_sip: Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/Info/info/4096/is_mode_sip_h323: Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/Info/info/4096/is_mode_sip_h32x: Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/Info/is_mode_sip_sccp: Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/Info/info/4096/is_mode_sip_default: Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/Info/info/4096/ccsip_iwf_set_tdm_ip_call_active: Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_default_mid_dialog_container Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:CNFSM_NO_STATE_CHANGE Apr 9 10:11:28.539: //556194/6F9B310C81DB/SIP/State/ccsip_cnfsm_debugs: OA:next_state:S_SIP_MID_DIALOG_IDLE Apr 9 10:11:28.540: //556194/6F9B310C81DB/SIP/Info/info/4096/sipSPISendAck: Associated container=0x7FFDB332AE98 to Ack Apr 9 10:11:28.540: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Apr 9 10:11:28.540: //556194/6F9B310C81DB/SIP/Transport/sipSPISendAck: Sending ACK to the transport layer Apr 9 10:11:28.540: //556194/6F9B310C81DB/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Dial peer configuration, Switch Transport is FALSE Apr 9 10:11:28.540: //556194/6F9B310C81DB/SIP/Transport/sipSPITransportSendMessage: msg=0x7FFDB2D061F8, addr=10.1.128.135, port=5060, sentBy_port=0, local_addr=10.50.66.1, is_req=1, transport=2, switch=0, callBack=0x7FFE0B237B90 Apr 9 10:11:28.540: //556194/6F9B310C81DB/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:28.540: //556194/6F9B310C81DB/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:28.540: //556194/6F9B310C81DB/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 9 10:11:28.540: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.1.128.135, rport:5060 with laddr:10.50.66.1 Apr 9 10:11:28.540: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: gcb=0x7FFDA8B9A2E8 is already on connection=0x7FFDA0F7BF18 context_list Apr 9 10:11:28.540: //556194/6F9B310C81DB/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x7FFDB2D061F8 Apr 9 10:11:28.540: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x7FFDB2D061F8, addr=10.1.128.135, port=5060, local_addr=10.50.66.1, connId=65 vrfid=0 for TCP Apr 9 10:11:28.540: //556194/6F9B310C81DB/SIP/State/sipSPIChangeState: 0x7FFDA8B9A2E8 : State change from (SIP_STATE_RECD_SUCCESS, SUBSTATE_NONE) to (STATE_ACTIVE, SUBSTATE_NONE) Apr 9 10:11:28.540: //556194/6F9B310C81DB/SIP/Info/info/4096/ccsip_offer_ans_handle_update_allowed: Apr 9 10:11:28.540: //556194/6F9B310C81DB/SIP/Call/sipSPICallInfo: The Call Setup Information is: Call Control Block (CCB) : 0x0x7FFDA8B9A2E8 State of The Call : STATE_ACTIVE TCP Sockets Used : YES Calling Number : +41797329888 Called Number : +35020002523 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:5060 Destination Name : 10.1.128.135 Apr 9 10:11:28.540: //556194/6F9B310C81DB/SIP/Call/sipSPIMediaCallInfo: Number of Media Streams: 1 Media Stream : 1 Negotiated Codec : g711ulaw Negotiated Codec Bytes : 160 Nego. Codec payload : 0 (tx), 0 (rx) Negotiated Dtmf-relay : 6 Dtmf-relay Payload : 101 (tx), 101 (rx) Source IP Address (Media): 10.50.66.1 Source IP Port (Media): 20242 Destn IP Address (Media): 10.50.80.1 Destn IP Port (Media): 21468 Orig Destn IP Address:Port (Media): [ - ]:0 Apr 9 10:11:28.540: //556194/6F9B310C81DB/SIP/Info/verbose/4096/sipSPICallActive: Transaction Complete. Lock on Facilities released. Apr 9 10:11:28.540: //556194/6F9B310C81DB/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Apr 9 10:11:28.540: //556194/6F9B310C81DB/SIP/Info/verbose/4096/sipSPIProcessCachedRequestEvent: No cached request event Apr 9 10:11:28.540: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x7FFDB33E7D50) counter, current msg->refCount = 1 Apr 9 10:11:28.540: //556194/6F9B310C81DB/SIP/Info/info/4096/ccsip_bridge: confID = 403, srcCallID = 556194, dstCallID = 556193 Apr 9 10:11:28.540: //556194/6F9B310C81DB/SIP/Info/verbose/1/sipSPIUupdateCcCallIds: Old src/dest ccCallids: -1/-1, new src/dest ccCallids: 556194/556193 Apr 9 10:11:28.540: //556194/6F9B310C81DB/SIP/Info/verbose/1/sipSPIUupdateCcCallIds: Old streamcallid=556194, new streamcallid=556194 Apr 9 10:11:28.540: //556194/6F9B310C81DB/SIP/Info/info/4096/ccsip_iwf_handle_generic_event: Apr 9 10:11:28.541: //556194/6F9B310C81DB/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_CALL_BRIDGE Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Info/verbose/4096/ccsip_iwf_process_event: IWF - cnfsm ret 2 Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Info/notify/256/ccsip_bridge: xcoder_attached = 0, xmitFunc = 0x7FFE098785F0, ccb xmitFunc = 0x7FFE098785F0 Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Info/info/24576/ccsip_spi_check_call_locally_held: CCSIP: call is locally noton-hold Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Media/sipSPIProcessRtpSessions: Processing stream state = STREAM_ADDING Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Info/verbose/6/sipSPIAddStream: set stream_callid from ccb->ccCallID:0x87CA2, media_type:0 Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Media/sipSPIAddStream: Adding stream 1 of type voice+dtmf (callid 556194) to the VOIP RTP library Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Info/notify/6/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Info/verbose/513/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.50.66.1 Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1 Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Info/info/1/sipSPIAssignStreamCallId: Assigning streamid 556194 to stream 1. Old streamid = 556194 Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Info/info/8192/sipSPIUpdateRtcpSession: ccb->flags != LOOPBACK Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Media/sipSPIUpdateRtcpSession: setting do_rtcp= TRUE for non forked leg 1 Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Info/info/1/is_call_held: Remote media IP addr: 10.50.80.1 Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Info/info/1/is_call_held: Media IP Addr 10.50.80.1, RTCP Type 3 Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info laddr = 10.50.66.1, lport = 20242, raddr = 10.50.80.1, rport=21468, do_rtcp=TRUE src_callid = 556194, dest_callid = 556193, stream type = voice+dtmf, stream direction = SENDRECV media_ip_addr = 10.50.80.1, vrf tableid = 0 media_addr_type = 1 negotiated_bandwidth (kbps) = 0 srtp_services = 0 nat_flag = 0 Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Media/sipSPIUpdateRtcpSession: RTP session already created - update Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Media/sipSPIUpdateRtpSession: stun is disabled for stream:7FFDA4A8E8D8 Apr 9 10:11:28.541: //556194/6F9B310C81DB/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:11:28.541: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIUpdateRtcpSession: VQM: gccb=0x0, gccb->callId=0, ccb->ccCallID=556194 Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Info/notify/8193/sipSPICreateAndStartRtpTimer: Media Inactivity Timer is disabled. Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Info/notify/2080/sipSPIUpdateRtcpSession: DTMF inb/oob disabled Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Info/verbose/4097/sipSPI_ipip_is_escalation: local channels = 0, peer channels = 0 Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Media/sipSPIGetNewLocalMediaDirection: New Remote Media Direction = SENDRECV Present Local Media Direction = SENDRECV New Local Media Direction = SENDRECV retVal = 0 Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/State/sipSPIChangeStreamState: Stream (callid = 556194) State changed from (STREAM_ADDING) to (STREAM_ACTIVE) Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Info/critical/32/ccsip_bridge: really can't find peer_stream for dtmf-relay interworking Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Info/notify/32/ccsip_bridge: set dtmf_iw_enabled to FALSE Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Info/info/4096/ccsip_run_deferred_media_negotiate: Apr 9 10:11:28.541: //556194/6F9B310C81DB/SIP/Info/info/4096/ccsip_is_media_negotiate_app_trigger_reinvite_deferred: retVal : 0 Apr 9 10:11:28.542: //556194/6F9B310C81DB/SIP/Info/verbose/4096/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 3, Event Id: CC_EV_CALL_FEATURE Apr 9 10:11:28.542: //556194/6F9B310C81DB/SIP/Info/verbose/4096/ccsip_iwf_map_ccapi_event_to_iwf_event: IWF Event: E_SIP_IWF_EV_PEER_CAPS Apr 9 10:11:28.542: //556194/6F9B310C81DB/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_PEER_CAPS Apr 9 10:11:28.542: //556194/6F9B310C81DB/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Apr 9 10:11:28.542: //556194/6F9B310C81DB/SIP/Info/info/4096/is_mode_sip_sccp_do_video: Apr 9 10:11:28.542: //556194/6F9B310C81DB/SIP/Info/info/4096/sip_iwf_def_peer_caps_ind_hdlr: Apr 9 10:11:28.542: //556194/6F9B310C81DB/SIP/Info/verbose/4097/ccsip_get_rtcp_session_parameters: CURRENT VALUES: stream_callid=556194, current_seq_num=0x15DD Apr 9 10:11:28.542: //556194/6F9B310C81DB/SIP/Info/verbose/4097/ccsip_get_rtcp_session_parameters: NEW VALUES: stream_callid=556194, current_seq_num=0x240C Apr 9 10:11:28.542: //556194/6F9B310C81DB/SIP/Info/info/1/sip_iwf_def_process_caps_ind: Load DSP with negotiated codec: g711ulaw, Bytes=160 Apr 9 10:11:28.542: //556194/6F9B310C81DB/SIP/Info/verbose/1/sip_iwf_def_process_caps_ind: Set forking flag to 0x0 Apr 9 10:11:28.542: //556194/6F9B310C81DB/SIP/Info/info/32/sipSPISetDTMFRelayMode: Set DSP for dtmf-relay = CC_CAP_DTMF_RELAY_NTE_AND_OOB with rx payload = 101, tx payload = 101 Apr 9 10:11:28.542: //556194/6F9B310C81DB/SIP/Info/info/10241/sip_set_modem_caps: Preferred (or the one that came from DSM) modem relay=1, from CLI config=0 Apr 9 10:11:28.542: //556194/6F9B310C81DB/SIP/Info/verbose/12288/sipSPIGetModemInfoPerCall: peer_callID=556193 Apr 9 10:11:28.542: //556194/6F9B310C81DB/SIP/Info/info/8193/sip_set_modem_caps: Disabling Modem Relay... Apr 9 10:11:28.542: //556194/6F9B310C81DB/SIP/Info/info/8193/sip_set_modem_caps: Negotiation already Done. Set negotiated Modem caps and generate SDP Xcap list Apr 9 10:11:28.542: //556194/6F9B310C81DB/SIP/Info/info/8193/sip_set_modem_caps: Modem Relay & Passthru both disabled Apr 9 10:11:28.542: //556194/6F9B310C81DB/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:11:28.542: //556194/6F9B310C81DB/SIP/Media/sipSPISetStreamInfo: 1 Active Streams Apr 9 10:11:29.187: //556195/000000000000/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x7FFDA8AFBAB8 Apr 9 10:11:29.187: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[567303] Apr 9 10:11:29.187: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB2D061F8 Apr 9 10:11:33.132: ISDN Se0/1/0:15 Q931: RX <- DISCONNECT pd = 8 callref = 0x0001 Cause i = 0x8A90 - Normal call clearing Progress Ind i = 0x8288 - In-band info or appropriate now available Apr 9 10:11:33.133: ISDN Se0/1/0:15 Q931: call_disc: PI received in disconnect; Postpone sending RELEASE for callid 0x20D Apr 9 10:11:33.134: //556194/6F9B310C81DB/SIP/Info/verbose/4096/ccsip_ipip_media_service_get_event_data: Event id = 18 Apr 9 10:11:33.134: //556194/6F9B310C81DB/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:11:33.134: //556194/6F9B310C81DB/SIP/Info/verbose/256/sipSPIResetXcoder: *****CLEANING UP XCODER RESOURCES***** Apr 9 10:11:33.134: //556194/6F9B310C81DB/SIP/Info/verbose/256/sipSPIResetXcoder: *****CLEANING UP XCODER RESOURCES***** Apr 9 10:11:33.134: //556194/6F9B310C81DB/SIP/Info/verbose/256/sipSPIResetXcoder: Xcoder resource already cleaned up Apr 9 10:11:33.134: //556194/6F9B310C81DB/SIP/State/ccsip_cnfsm_debugs: IPIPMS:next_state:S_IPIP_MEDIA_SERV_STATE_IDLE Apr 9 10:11:33.134: //556194/6F9B310C81DB/SIP/Media/sipSPIUpdateRtpSession: stun is disabled for stream:7FFDA4A8E8D8 Apr 9 10:11:33.136: //556194/6F9B310C81DB/SIP/Info/verbose/8192/ccsip_call_statistics: Requesting stats for callid=556194 Apr 9 10:11:33.136: //556194/6F9B310C81DB/SIP/Info/verbose/4096/ccsip_ipip_media_service_get_event_data: Event id = 29 Apr 9 10:11:33.136: //556194/6F9B310C81DB/SIP/Info/critical/32768/ccsip_ipip_media_forking_post_event: MF: Not a Anchor SIP leg.. Apr 9 10:11:33.136: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT Apr 9 10:11:33.138: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 8 Apr 9 10:11:33.138: //556194/6F9B310C81DB/SIP/Info/info/133120/sipSPIBwCacReleaseDialPeerBw: bwcac dial-peer bw 80 Kbps released for tag 500 active bw 0 Kbps Apr 9 10:11:33.138: //556194/6F9B310C81DB/SIP/Info/info/131072/sipSPIBwCacReleaseInterfaceBw: bwcac releasing interface Loopback0 bw 80 Kbps Apr 9 10:11:33.138: //556194/6F9B310C81DB/SIP/Info/info/131072/sipSPIBwCacReleaseAccountedBw: bwcac released accounted bw 80000 bps Apr 9 10:11:33.138: //556194/6F9B310C81DB/SIP/Info/notify/4096/act_active_disconnect: Disconnect deferred, as stats request pending Apr 9 10:11:33.138: //556194/6F9B310C81DB/SIP/Info/info/4096/sipSPISetCommonTimer: Started generic timer type 2 for 240000 millisecs Apr 9 10:11:33.162: //556194/6F9B310C81DB/SIP/Info/verbose/32768/ccsip_indicate_rt_packet_stats: Processing stats for callid=556194, proc_id=1 Apr 9 10:11:33.162: //556194/6F9B310C81DB/SIP/Info/verbose/4096/ccsip_ipip_media_service_get_event_data: Event id = 29 Apr 9 10:11:33.163: //556194/6F9B310C81DB/SIP/Info/critical/32768/ccsip_ipip_media_forking_post_event: MF: Not a Anchor SIP leg.. Apr 9 10:11:33.163: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT Apr 9 10:11:33.163: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 8 Apr 9 10:11:33.163: //556194/6F9B310C81DB/SIP/Info/info/4096/act_active_disconnect: act_active_disconnect: Disconnect now.. no defer BYE.. Apr 9 10:11:33.163: //556194/6F9B310C81DB/SIP/Info/info/4096/sipSPIStopHoldTimer: Stopping hold timer Apr 9 10:11:33.163: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB3117480 with refCount = 1 Apr 9 10:11:33.163: //556194/6F9B310C81DB/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 3 event Apr 9 10:11:33.163: //556194/6F9B310C81DB/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Apr 9 10:11:33.163: //556194/6F9B310C81DB/SIP/Info/notify/4096/sipSPI_ipip_GetPassthruCopyListDataFromTdContainer: Could not get any elements from TD Container Apr 9 10:11:33.163: //556194/6F9B310C81DB/SIP/Info/info/4096/sipSPIStopHoldTimer: Stopping hold timer Apr 9 10:11:33.164: //556194/6F9B310C81DB/SIP/Info/info/4096/sipSPISendBye: Associated container=0x7FFDB3326238 to Bye Apr 9 10:11:33.164: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Apr 9 10:11:33.164: //556194/6F9B310C81DB/SIP/Transport/sipSPISendBye: Sending BYE to the transport layer Apr 9 10:11:33.164: //556194/6F9B310C81DB/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Dial peer configuration, Switch Transport is FALSE Apr 9 10:11:33.164: //556194/6F9B310C81DB/SIP/Transport/sipSPITransportSendMessage: msg=0x7FFDB3117480, 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:11:33.164: //556194/6F9B310C81DB/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:33.164: //556194/6F9B310C81DB/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:33.164: //556194/6F9B310C81DB/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 9 10:11:33.164: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.1.128.135, rport:5060 with laddr:10.50.66.1 Apr 9 10:11:33.164: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: gcb=0x7FFDA8B9A2E8 is already on connection=0x7FFDA0F7BF18 context_list Apr 9 10:11:33.164: //556194/6F9B310C81DB/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x7FFDB3117480 Apr 9 10:11:33.164: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x7FFDB3117480, addr=10.1.128.135, port=5060, local_addr=10.50.66.1, connId=65 vrfid=0 for TCP Apr 9 10:11:33.164: //556194/6F9B310C81DB/SIP/Info/info/512/sentByeDisconnecting: Sent Bye Request, starting DisconnectTimer Apr 9 10:11:33.164: //556194/6F9B310C81DB/SIP/State/sipSPIChangeState: 0x7FFDA8B9A2E8 : State change from (STATE_ACTIVE, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE) Apr 9 10:11:33.164: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_tcp_queue_event: Event type: send msg, connid: 65, fd: 7 Apr 9 10:11:33.164: //556194/6F9B310C81DB/SIP/Msg/ccsipDisplayMsg: Sent: BYE sip:+35020002523@10.1.128.135:5060;transport=tcp SIP/2.0 Via: SIP/2.0/TCP 10.50.66.1:5060;branch=z9hG4bK56C8815DD From: ;tag=7AA28134-536 To: ;tag=20449157~066d7f19-322a-43ba-8eca-ef58947b04ca-62721648 Date: Mon, 09 Apr 2018 08:11:27 GMT Call-ID: 6F9C429F-3B0411E8-93F0AD25-DD7BDD2E@10.50.66.1 User-Agent: Cisco-SIPGateway/IOS-15.4.3.S4 Max-Forwards: 70 Timestamp: 1523261493 CSeq: 102 BYE Reason: Q.850;cause=16 Content-Length: 0 Apr 9 10:11:33.164: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB3117480 Apr 9 10:11:33.194: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x7FFDA8AFBAB8) with key=[567304] to table Apr 9 10:11:33.194: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init: Apr 9 10:11:33.194: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init: Apr 9 10:11:33.195: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised.. Apr 9 10:11:33.195: //-1/000000000000/SIP/Info/verbose/4097/ccsip_platform_init_ccb: Initialising rtp session queue Apr 9 10:11:33.195: //556196/000000000000/SIP/State/sipSPIChangeState: 0x7FFDA8AFBAB8 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Apr 9 10:11:33.195: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 37 Apr 9 10:11:33.195: //556196/000000000000/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable: Adding call id 87CA4 to table Apr 9 10:11:33.195: //556196/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Apr 9 10:11:33.195: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.50.66.1 for SIP Apr 9 10:11:33.195: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.50.66.1 for SIP Apr 9 10:11:33.195: //556196/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 10.50.66.1 Apr 9 10:11:33.195: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 10.50.66.1 Apr 9 10:11:33.195: //556196/000000000000/SIP/Info/verbose/4096/sipSPIUaddCcbToUACTable: ****Adding to UAC table.0x7FFDA8AFBAB8 731C68FB-3B0411E8-93F2AD25-DD7BDD2E@10.50.66.1 Apr 9 10:11:33.195: //556196/000000000000/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x7FFDA8AFBAB8 key=731C68FB-3B0411E8-93F2AD25-DD7BDD2E@10.50.66.1 balance 0 Apr 9 10:11:33.195: //556196/000000000000/SIP/State/sipSPIChangeState: 0x7FFDA8AFBAB8 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_NONE) Apr 9 10:11:33.195: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB3117480 with refCount = 1 Apr 9 10:11:33.195: //556196/000000000000/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 15 event Apr 9 10:11:33.195: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone MEZ_SZ to SIP default timezone = GMT Apr 9 10:11:33.195: //556196/000000000000/SIP/Error/sipSPIAddPrivacyHeader: Orig Container is NULL...should have value except in case of sending OOD Options ping. Apr 9 10:11:33.196: //556196/000000000000/SIP/Error/sipSPIAddAssertedIDHeader: Orig Container is NULL...should have value except in case of sending OOD Options ping. Apr 9 10:11:33.196: //556196/000000000000/SIP/Error/sipSPIAddPreferredIDHeader: Orig Container is NULL...should have value except in case of sending OOD Options ping. Apr 9 10:11:33.196: //556196/000000000000/SIP/Info/info/4096/sipSPISendOptionsRequest: Associated container=0x7FFDB33224E0 to Options Apr 9 10:11:33.196: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Apr 9 10:11:33.196: //556196/000000000000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Dial peer configuration, Switch Transport is FALSE Apr 9 10:11:33.196: //556196/000000000000/SIP/Transport/sipSPITransportSendMessage: msg=0x7FFDB3117480, 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:11:33.196: //556196/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:33.196: //556196/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:33.196: //556196/000000000000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 9 10:11:33.196: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.1.192.132, rport:5060 with laddr:10.50.66.1 Apr 9 10:11:33.196: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x7FFDA8AFBAB8 with connection=0x7FFDA0F7D498 context list Apr 9 10:11:33.196: //556196/000000000000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x7FFDB3117480 Apr 9 10:11:33.196: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x7FFDB3117480, addr=10.1.192.132, port=5060, local_addr=10.50.66.1, connId=60 vrfid=0 for TCP Apr 9 10:11:33.196: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_tcp_queue_event: Event type: send msg, connid: 60, fd: 4 Apr 9 10:11:33.196: //556196/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=z9hG4bK56C8915CB From: ;tag=7AA29824-1A7A To: Date: Mon, 09 Apr 2018 08:11:33 GMT Call-ID: 731C68FB-3B0411E8-93F2AD25-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:11:33.196: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB3117480 Apr 9 10:11:33.214: ISDN Se0/1/0:15 Q931: TX -> RELEASE pd = 8 callref = 0x8001 Apr 9 10:11:33.223: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 7 to index 65 Apr 9 10:11:33.223: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB2D97B60 with refCount = 1 Apr 9 10:11:33.223: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB3117480 with refCount = 1 Apr 9 10:11:33.223: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB2D97B60 Apr 9 10:11:33.223: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Apr 9 10:11:33.223: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x7FFDA0BDA5E8 Apr 9 10:11:33.223: //-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:11:33.223: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 5060 connId 65 Apr 9 10:11:33.223: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Apr 9 10:11:33.223: //556194/6F9B310C81DB/SIP/Info/info/1024/sipSPIMatchRespToReqTran: removing unneeded z9hG4bK56C8815DD from via branch list Apr 9 10:11:33.223: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x7FFDB3117480) counter, current msg->refCount = 2 Apr 9 10:11:33.223: //556194/6F9B310C81DB/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 200 OK Via: SIP/2.0/TCP 10.50.66.1:5060;branch=z9hG4bK56C8815DD From: ;tag=7AA28134-536 To: ;tag=20449157~066d7f19-322a-43ba-8eca-ef58947b04ca-62721648 Date: Mon, 09 Apr 2018 08:11:33 GMT Call-ID: 6F9C429F-3B0411E8-93F0AD25-DD7BDD2E@10.50.66.1 Server: Cisco-CUCM10.5 CSeq: 102 BYE Content-Length: 0 Apr 9 10:11:33.223: //556194/6F9B310C81DB/SIP/Info/verbose/1024/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX Apr 9 10:11:33.224: //556194/6F9B310C81DB/SIP/Info/sact_disconnecting_new_message_response: [sact_disconnecting_new_message_response] Received Response Class [2] Method Code [103] Apr 9 10:11:33.224: //556194/6F9B310C81DB/SIP/Info/info/4096/sipSPISetCommonTimer: Stopping timer type 2 to start 2 Apr 9 10:11:33.224: //556194/6F9B310C81DB/SIP/Info/info/4096/sipSPISetCommonTimer: Started generic timer type 2 for 240000 millisecs Apr 9 10:11:33.224: //556194/6F9B310C81DB/SIP/Info/info/12288/sipSPIDeleteRtpDPSession: Calling delete dp session Apr 9 10:11:33.224: //556194/6F9B310C81DB/SIP/Info/verbose/4096/sipSPICallCloseAfterFinalStat: sipSPICallCloseAfterFinalStat: Apr 9 10:11:33.224: //556194/6F9B310C81DB/SIP/Info/info/12288/sipSPIIcpifUpdate: CallState: 4 Playout: 0 DiscTime:205737817 ConnTime 205737348 Apr 9 10:11:33.224: //556194/6F9B310C81DB/SIP/Media/sipSPIHandleDestroyRtpSession: stream:7FFDA4A8E8D8 Apr 9 10:11:33.224: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB33E7D50 Apr 9 10:11:33.224: //556194/6F9B310C81DB/SIP/State/sipSPIChangeState: 0x7FFDA8B9A2E8 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE) Apr 9 10:11:33.224: //556194/6F9B310C81DB/SIP/Call/sipSPICallInfo: The Call Setup Information is: Call Control Block (CCB) : 0x0x7FFDA8B9A2E8 State of The Call : STATE_DEAD TCP Sockets Used : YES Calling Number : +41797329888 Called Number : +35020002523 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:5060 Destination Name : 10.1.128.135 Apr 9 10:11:33.224: //556194/6F9B310C81DB/SIP/Call/sipSPIMediaCallInfo: Number of Media Streams: 1 Media Stream : 1 Negotiated Codec : g711ulaw Negotiated Codec Bytes : 160 Nego. Codec payload : 0 (tx), 0 (rx) Negotiated Dtmf-relay : 6 Dtmf-relay Payload : 101 (tx), 101 (rx) Source IP Address (Media): 10.50.66.1 Source IP Port (Media): 20242 Destn IP Address (Media): 10.50.80.1 Destn IP Port (Media): 21468 Orig Destn IP Address:Port (Media): [ - ]:0 Apr 9 10:11:33.224: //556194/6F9B310C81DB/SIP/Call/sipSPICallInfo: Disconnect Cause (CC) : 16 Disconnect Cause (SIP) : 200 Apr 9 10:11:33.224: //556194/6F9B310C81DB/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 87CA2 Apr 9 10:11:33.224: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[567302] removed. Apr 9 10:11:33.224: //556194/6F9B310C81DB/SIP/Info/info/4096/sipSPIStopCommonTimer: Stopping Generic Timer 2 Apr 9 10:11:33.224: //556194/6F9B310C81DB/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x7FFDA8B9A2E8 key=6F9C429F-3B0411E8-93F0AD25-DD7BDD2E@10.50.66.1 Apr 9 10:11:33.224: //556194/6F9B310C81DB/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Apr 9 10:11:33.225: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x7FFDA0BDA5E8, addr=10.1.128.135, port=5060, local_addr=10.50.66.1, unregistering context=0x7FFDA8B9A2E8 Apr 9 10:11:33.225: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x7FFDA8B9A2E8 from the connection=0x7FFDA0F7BF18 context list Apr 9 10:11:33.225: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x7FFDB3117480) counter, current msg->refCount = 1 Apr 9 10:11:33.225: //556194/6F9B310C81DB/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Apr 9 10:11:33.225: //556194/6F9B310C81DB/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer Apr 9 10:11:33.225: //556194/6F9B310C81DB/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x7FFDA8B9A2E8 Apr 9 10:11:33.225: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[567302] Apr 9 10:11:33.225: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB3117480 Apr 9 10:11:33.252: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 4 to index 60 Apr 9 10:11:33.252: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB3117480 with refCount = 1 Apr 9 10:11:33.252: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB2D97B60 with refCount = 1 Apr 9 10:11:33.252: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB3117480 Apr 9 10:11:33.252: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Apr 9 10:11:33.252: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x7FFDA0BDA5E8 Apr 9 10:11:33.252: //-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:11:33.252: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 5060 connId 60 Apr 9 10:11:33.252: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Apr 9 10:11:33.253: //556196/000000000000/SIP/Info/info/1024/sipSPIMatchRespToReqTran: removing unneeded z9hG4bK56C8915CB from via branch list Apr 9 10:11:33.253: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x7FFDB2D97B60) counter, current msg->refCount = 2 Apr 9 10:11:33.253: //556196/000000000000/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 503 Service Unavailable Via: SIP/2.0/TCP 10.50.66.1:5060;branch=z9hG4bK56C8915CB From: ;tag=7AA29824-1A7A To: ;tag=363917617 Date: Mon, 09 Apr 2018 08:11:33 GMT Call-ID: 731C68FB-3B0411E8-93F2AD25-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:11:33.253: //556196/000000000000/SIP/Info/verbose/1024/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX Apr 9 10:11:33.253: //556196/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:11:33.253: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x7FFDB2D97B60) counter, current msg->refCount = 1 Apr 9 10:11:33.253: //556196/000000000000/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 87CA4 Apr 9 10:11:33.253: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[567304] removed. Apr 9 10:11:33.253: //556196/000000000000/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x7FFDA8AFBAB8 key=731C68FB-3B0411E8-93F2AD25-DD7BDD2E@10.50.66.1 Apr 9 10:11:33.253: //556196/000000000000/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Apr 9 10:11:33.253: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x7FFDA0BDA5E8, addr=10.1.192.132, port=5060, local_addr=10.50.66.1, unregistering context=0x7FFDA8AFBAB8 Apr 9 10:11:33.253: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x7FFDA8AFBAB8 from the connection=0x7FFDA0F7D498 context list Apr 9 10:11:33.253: //556196/000000000000/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Apr 9 10:11:33.253: //556196/000000000000/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer Apr 9 10:11:33.253: //556196/000000000000/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x7FFDA8AFBAB8 Apr 9 10:11:33.253: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[567304] Apr 9 10:11:33.253: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB2D97B60 Apr 9 10:11:33.290: ISDN Se0/1/0:15 Q931: RX <- RELEASE_COMP pd = 8 callref = 0x0001 Apr 9 10:11:34.122: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x7FFDA8AFBAB8) with key=[567305] to table Apr 9 10:11:34.122: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init: Apr 9 10:11:34.122: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init: Apr 9 10:11:34.122: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised.. Apr 9 10:11:34.122: //-1/000000000000/SIP/Info/verbose/4097/ccsip_platform_init_ccb: Initialising rtp session queue Apr 9 10:11:34.122: //-1/000000000000/SIP/Info/notify/262144/ccsipRegisterSetTargetInfo: p2p mode with Registrar Server = ipv4:10.50.66.1 Apr 9 10:11:34.122: //-1/000000000000/SIP/Info/verbose/262144/ccsipRegisterSetTargetInfo: Parsing The Registrar Address Apr 9 10:11:34.122: //-1/xxxxxxxxxxxx/SIP/Info/verbose/5120/sipSPIGetOutboundHostAndDestHostPrivate: CCSIP: target_host : 10.50.66.1 target_port : 5060 Apr 9 10:11:34.122: //-1/000000000000/SIP/Info/verbose/5120/sipSPIValidateAndCopyOutboundHost: CCSIP: copy target_host to outbound_host Apr 9 10:11:34.122: //-1/000000000000/SIP/Info/critical/8192/sipSPIOutboundProxyReuse: Do not reuse Outbound Proxy IP adress and Port Apr 9 10:11:34.122: //-1/000000000000/SIP/State/sipSPIChangeState: 0x7FFDA8AFBAB8 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Apr 9 10:11:34.122: //-1/000000000000/SIP/Info/verbose/6144/ccsip_spi_registrar_add_expires_header: Inside ccsip_spi_registrar_add_expires_header for Expires Apr 9 10:11:34.123: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_OUTBOUND_REGISTER Apr 9 10:11:34.123: //-1/xxxxxxxxxxxx/SIP/Info/info/262144/sipSPIIncrementOverloadCount: Local 1 Global 1 Apr 9 10:11:34.123: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 40 Apr 9 10:11:34.123: //-1/000000000000/SIP/Info/verbose/262144/act_idle_outgoing_register: In act_idle_outgoing_register Apr 9 10:11:34.123: //556197/000000000000/SIP/Info/info/262144/act_idle_outgoing_register: Send REGISTER to 10.50.66.1:5060 Apr 9 10:11:34.123: //556197/000000000000/SIP/Info/verbose/4096/sipSPIUaddCcbToUACTable: ****Adding to UAC table.0x7FFDA8AFBAB8 FFFFFFFF993B71AD-39D411E8-FFFFFFFF9327AD25-FFFFFFFFDD7BDD2E Apr 9 10:11:34.123: //556197/000000000000/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x7FFDA8AFBAB8 key=FFFFFFFF993B71AD-39D411E8-FFFFFFFF9327AD25-FFFFFFFFDD7BDD2E balance 1 Apr 9 10:11:34.123: //556197/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Apr 9 10:11:34.123: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.50.66.1 for SIP Apr 9 10:11:34.123: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.50.66.1 for SIP Apr 9 10:11:34.123: //556197/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 10.50.66.1 Apr 9 10:11:34.123: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 10.50.66.1 Apr 9 10:11:34.123: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB2D97B60 with refCount = 1 Apr 9 10:11:34.123: //556197/000000000000/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 7 event Apr 9 10:11:34.123: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB Apr 9 10:11:34.123: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB Apr 9 10:11:34.123: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone MEZ_SZ to SIP default timezone = GMT Apr 9 10:11:34.123: //556197/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:34.123: //556197/000000000000/SIP/Info/info/4096/sipSPISendRegister: Associated container=0x7FFDB3322270 to Register Apr 9 10:11:34.123: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Apr 9 10:11:34.123: //556197/000000000000/SIP/Transport/sipSPISendRegister: Sending REGISTER to the transport layer Apr 9 10:11:34.123: //556197/000000000000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE Apr 9 10:11:34.123: //556197/000000000000/SIP/Transport/sipSPITransportSendMessage: msg=0x7FFDB2D97B60, addr=10.50.66.1, port=5060, sentBy_port=0, local_addr=10.50.66.1, is_req=1, transport=1, switch=0, callBack=0x7FFE0B237D40 Apr 9 10:11:34.123: //556197/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:34.123: //556197/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:34.123: //556197/000000000000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 9 10:11:34.124: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.50.66.1, rport:5060 with laddr:10.50.66.1 Apr 9 10:11:34.124: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x7FFDA8AFBAB8 with connection=0x7FFDA0F7D340 context list Apr 9 10:11:34.124: //556197/000000000000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x7FFDB2D97B60 Apr 9 10:11:34.124: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x7FFDB2D97B60, addr=10.50.66.1, port=5060, local_addr=10.50.66.1, connId=3 vrfid=0 for UDP Apr 9 10:11:34.124: //556197/000000000000/SIP/State/sipSPIChangeState: 0x7FFDA8AFBAB8 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) Apr 9 10:11:34.124: //556197/000000000000/SIP/State/sipSPIChangeState: 0x7FFDA8AFBAB8 : State change from (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) Apr 9 10:11:34.124: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: REGISTER sip:10.50.66.1:5060 SIP/2.0 Via: SIP/2.0/UDP 10.50.66.1:5060;branch=z9hG4bK56C8ADB0 From: ;tag=7AA29BC4-663 To: Date: Mon, 09 Apr 2018 08:11:34 GMT Call-ID: FFFFFFFF993B71AD-39D411E8-FFFFFFFF9327AD25-FFFFFFFFDD7BDD2E User-Agent: Cisco-SIPGateway/IOS-15.4.3.S4 Max-Forwards: 70 Timestamp: 1523261494 CSeq: 725 REGISTER Contact: Expires: 3600 Supported: path Content-Length: 0 Apr 9 10:11:34.124: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB2D97B60 Apr 9 10:11:34.124: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB2D97B60 with refCount = 1 Apr 9 10:11:34.124: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB3117480 with refCount = 1 Apr 9 10:11:34.124: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [10.50.66.1]:55554, local_address:[10.50.66.1] Apr 9 10:11:34.124: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB2D97B60 Apr 9 10:11:34.124: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Apr 9 10:11:34.124: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Apr 9 10:11:34.125: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: REGISTER sip:10.50.66.1:5060 SIP/2.0 Via: SIP/2.0/UDP 10.50.66.1:5060;branch=z9hG4bK56C8ADB0 From: ;tag=7AA29BC4-663 To: Date: Mon, 09 Apr 2018 08:11:34 GMT Call-ID: FFFFFFFF993B71AD-39D411E8-FFFFFFFF9327AD25-FFFFFFFFDD7BDD2E User-Agent: Cisco-SIPGateway/IOS-15.4.3.S4 Max-Forwards: 70 Timestamp: 1523261494 CSeq: 725 REGISTER Contact: Expires: 3600 Supported: path Content-Length: 0 Apr 9 10:11:34.125: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Apr 9 10:11:34.125: //556197/000000000000/SIP/Info/info/4096/sipSPICheckFromToRequest: Trying with child CCB 0x0 index 0 curr_child 0 Apr 9 10:11:34.125: //556197/000000000000/SIP/Error/sipSPICheckFromToRequest: Failed FROM/TO Request check - IGNORE IF HAIRPIN CALL old_from: ;tag=7AA29BC4-663 old_to: new_from: ;tag=7AA29BC4-663 new_to: Apr 9 10:11:34.125: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x7FFDA8B9A2E8) with key=[567306] to table Apr 9 10:11:34.125: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init: Apr 9 10:11:34.125: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init: Apr 9 10:11:34.125: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised.. Apr 9 10:11:34.125: //-1/000000000000/SIP/Info/verbose/4097/ccsip_platform_init_ccb: Initialising rtp session queue Apr 9 10:11:34.125: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.50.66.1,Port 5060, Transport 1, SentBy Port 5060vrfid 0 Apr 9 10:11:34.125: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Apr 9 10:11:34.125: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.50.66.1 for SIP Apr 9 10:11:34.125: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.50.66.1 for SIP Apr 9 10:11:34.125: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 10.50.66.1 Apr 9 10:11:34.125: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 10.50.66.1 Apr 9 10:11:34.125: //-1/73AA518F93F3/SIP/State/sipSPIChangeState: 0x7FFDA8B9A2E8 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Apr 9 10:11:34.125: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.50.66.1,Port 55554, Transport 1, SentBy Port 5060vrfid 0 Apr 9 10:11:34.125: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone MEZ_SZ to SIP default timezone = GMT Apr 9 10:11:34.125: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.50.66.1,Port 55554, Transport 1, SentBy Port 5060vrfid 0 Apr 9 10:11:34.125: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x7FFDB3117480) counter, current msg->refCount = 2 Apr 9 10:11:34.125: //-1/73AA518F93F3/SIP/Info/verbose/4096/sipSPIAssignCcbLastRequest: Current ccb(0x7FFDA8B9A2E8)->last_request = 0x7FFDB3117480, refCount = 2 Apr 9 10:11:34.126: //-1/73AA518F93F3/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x7FFDA8B9A2E8 key=FFFFFFFF993B71AD-39D411E8-FFFFFFFF9327AD25-FFFFFFFFDD7BDD2E.7AA29BC4-663 balance 1 Apr 9 10:11:34.126: //556198/73AA518F93F3/SIP/Event/sact_idle_new_message_register: ccsip_api_register_ind return value : SIP_SUCCESS Apr 9 10:11:34.126: //556198/73AA518F93F3/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable: Adding call id 87CA6 to table Apr 9 10:11:34.126: //556198/73AA518F93F3/SIP/State/sipSPIChangeState: 0x7FFDA8B9A2E8 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE) Apr 9 10:11:34.126: //556198/73AA518F93F3/SIP/Info/notify/262144/ccsip_register_process_incoming_register: CCSIP_REGISTER:: REGISTER request Apr 9 10:11:34.126: //556198/73AA518F93F3/SIP/Info/notify/262144/ccsip_spi_register_incoming_registration: registration expires timer max is 3600 and min is 60 Apr 9 10:11:34.126: //556198/73AA518F93F3/SIP/Error/ccsip_spi_registration_failed: TDOS: Registration response consumed. Apr 9 10:11:34.126: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x7FFDB3117480) counter, current msg->refCount = 1 Apr 9 10:11:34.126: //556198/73AA518F93F3/SIP/State/sipSPIChangeState: 0x7FFDA8B9A2E8 : State change from (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Apr 9 10:11:34.624: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB2D97B60 with refCount = 1 Apr 9 10:11:34.624: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone MEZ_SZ to SIP default timezone = GMT Apr 9 10:11:34.625: //556197/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:34.625: //556197/000000000000/SIP/Info/info/4096/sipSPISendRegister: Associated container=0x7FFDB3322270 to Register Apr 9 10:11:34.625: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Apr 9 10:11:34.625: //556197/000000000000/SIP/Transport/sipSPISendRegister: Sending REGISTER to the transport layer Apr 9 10:11:34.625: //556197/000000000000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE Apr 9 10:11:34.625: //556197/000000000000/SIP/Transport/sipSPITransportSendMessage: msg=0x7FFDB2D97B60, addr=10.50.66.1, port=5060, sentBy_port=0, local_addr=10.50.66.1, is_req=1, transport=1, switch=0, callBack=0x0 Apr 9 10:11:34.625: //556197/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:34.625: //556197/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:34.625: //556197/000000000000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 9 10:11:34.625: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.50.66.1, rport:5060 with laddr:10.50.66.1 Apr 9 10:11:34.625: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: gcb=0x7FFDA8AFBAB8 is already on connection=0x7FFDA0F7D340 context_list Apr 9 10:11:34.625: //556197/000000000000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x7FFDB2D97B60 Apr 9 10:11:34.625: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x7FFDB2D97B60, addr=10.50.66.1, port=5060, local_addr=10.50.66.1, connId=3 vrfid=0 for UDP Apr 9 10:11:34.625: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: REGISTER sip:10.50.66.1:5060 SIP/2.0 Via: SIP/2.0/UDP 10.50.66.1:5060;branch=z9hG4bK56C8ADB0 From: ;tag=7AA29BC4-663 To: Date: Mon, 09 Apr 2018 08:11:34 GMT Call-ID: FFFFFFFF993B71AD-39D411E8-FFFFFFFF9327AD25-FFFFFFFFDD7BDD2E User-Agent: Cisco-SIPGateway/IOS-15.4.3.S4 Max-Forwards: 70 Timestamp: 1523261494 CSeq: 725 REGISTER Contact: Expires: 3600 Supported: path Content-Length: 0 Apr 9 10:11:34.625: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB2D97B60 Apr 9 10:11:34.626: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB2D97B60 with refCount = 1 Apr 9 10:11:34.626: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB333E108 with refCount = 1 Apr 9 10:11:34.626: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [10.50.66.1]:55554, local_address:[10.50.66.1] Apr 9 10:11:34.626: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB2D97B60 Apr 9 10:11:34.626: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Apr 9 10:11:34.626: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Apr 9 10:11:34.626: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: REGISTER sip:10.50.66.1:5060 SIP/2.0 Via: SIP/2.0/UDP 10.50.66.1:5060;branch=z9hG4bK56C8ADB0 From: ;tag=7AA29BC4-663 To: Date: Mon, 09 Apr 2018 08:11:34 GMT Call-ID: FFFFFFFF993B71AD-39D411E8-FFFFFFFF9327AD25-FFFFFFFFDD7BDD2E User-Agent: Cisco-SIPGateway/IOS-15.4.3.S4 Max-Forwards: 70 Timestamp: 1523261494 CSeq: 725 REGISTER Contact: Expires: 3600 Supported: path Content-Length: 0 Apr 9 10:11:34.626: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Apr 9 10:11:34.626: //556197/000000000000/SIP/Info/info/4096/sipSPICheckFromToRequest: Trying with child CCB 0x0 index 0 curr_child 0 Apr 9 10:11:34.626: //556197/000000000000/SIP/Error/sipSPICheckFromToRequest: Failed FROM/TO Request check - IGNORE IF HAIRPIN CALL old_from: ;tag=7AA29BC4-663 old_to: new_from: ;tag=7AA29BC4-663 new_to: Apr 9 10:11:34.626: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x7FFDA8BA1630) with key=[567307] to table Apr 9 10:11:34.626: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init: Apr 9 10:11:34.626: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init: Apr 9 10:11:34.626: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised.. Apr 9 10:11:34.626: //-1/000000000000/SIP/Info/verbose/4097/ccsip_platform_init_ccb: Initialising rtp session queue Apr 9 10:11:34.626: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.50.66.1,Port 5060, Transport 1, SentBy Port 5060vrfid 0 Apr 9 10:11:34.626: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Apr 9 10:11:34.626: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 10.50.66.1 for SIP Apr 9 10:11:34.626: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 10.50.66.1 for SIP Apr 9 10:11:34.626: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 10.50.66.1 Apr 9 10:11:34.626: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 10.50.66.1 Apr 9 10:11:34.627: //-1/73F6C28A93F4/SIP/State/sipSPIChangeState: 0x7FFDA8BA1630 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Apr 9 10:11:34.627: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.50.66.1,Port 55554, Transport 1, SentBy Port 5060vrfid 0 Apr 9 10:11:34.627: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone MEZ_SZ to SIP default timezone = GMT Apr 9 10:11:34.627: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.50.66.1,Port 55554, Transport 1, SentBy Port 5060vrfid 0 Apr 9 10:11:34.627: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x7FFDB333E108) counter, current msg->refCount = 2 Apr 9 10:11:34.627: //-1/73F6C28A93F4/SIP/Info/verbose/4096/sipSPIAssignCcbLastRequest: Current ccb(0x7FFDA8BA1630)->last_request = 0x7FFDB333E108, refCount = 2 Apr 9 10:11:34.627: //-1/73F6C28A93F4/SIP/Error/sipSPIUaddCcbToTable: Could not add ccb to table. ccb=0x7FFDA8BA1630 key=FFFFFFFF993B71AD-39D411E8-FFFFFFFF9327AD25-FFFFFFFFDD7BDD2E.7AA29BC4-663 Apr 9 10:11:34.627: //-1/73F6C28A93F4/SIP/Error/sact_idle_new_message_register: CCSIP_REGISTER:: Problem adding CCB to UAS Table Apr 9 10:11:34.627: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB2D97B60 with refCount = 1 Apr 9 10:11:34.627: //-1/73F6C28A93F4/SIP/Transport/sipSPISendResponse: Sending INFO Response to the transport layer Apr 9 10:11:34.627: //-1/73F6C28A93F4/SIP/Transport/sipSPITransportSendMessage: msg=0x7FFDB2D97B60, addr=10.50.66.1, port=55554, sentBy_port=5060, local_addr=10.50.66.1, is_req=0, transport=1, switch=0, callBack=0x7FFE0B2388A0 Apr 9 10:11:34.627: //-1/73F6C28A93F4/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:34.627: //-1/73F6C28A93F4/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Apr 9 10:11:34.627: //-1/73F6C28A93F4/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 9 10:11:34.627: //-1/73F6C28A93F4/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x7FFDB2D97B60 to default port=5060 Apr 9 10:11:34.627: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.50.66.1, rport:5060 with laddr:10.50.66.1 Apr 9 10:11:34.627: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x7FFDA8BA1630 with connection=0x7FFDA0F7D340 context list Apr 9 10:11:34.627: //-1/73F6C28A93F4/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x7FFDB2D97B60 Apr 9 10:11:34.627: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x7FFDB2D97B60, addr=10.50.66.1, port=5060, local_addr=10.50.66.1, connId=3 vrfid=0 for UDP Apr 9 10:11:34.628: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x7FFDB333E108) counter, current msg->refCount = 1 Apr 9 10:11:34.628: //-1/73F6C28A93F4/SIP/State/sipSPIChangeState: 0x7FFDA8BA1630 : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Apr 9 10:11:34.628: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 500 Internal Server Error Via: SIP/2.0/UDP 10.50.66.1:5060;branch=z9hG4bK56C8ADB0 From: ;tag=7AA29BC4-663 To: ;tag=7AA29DBC-223A Date: Mon, 09 Apr 2018 08:11:34 GMT Call-ID: FFFFFFFF993B71AD-39D411E8-FFFFFFFF9327AD25-FFFFFFFFDD7BDD2E Server: Cisco-SIPGateway/IOS-15.4.3.S4 Timestamp: 1523261494 CSeq: 725 REGISTER Content-Length: 0 Apr 9 10:11:34.628: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB2D97B60 Apr 9 10:11:34.628: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB2D97B60 with refCount = 1 Apr 9 10:11:34.628: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7FFDB2D061F8 with refCount = 1 Apr 9 10:11:34.628: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [10.50.66.1]:55554, local_address:[10.50.66.1] Apr 9 10:11:34.628: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7FFDB2D97B60 Apr 9 10:11:34.628: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Apr 9 10:11:34.628: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Apr 9 10:11:34.628: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Apr 9 10:11:34.629: //556197/000000000000/SIP/Info/info/1024/sipSPIMatchRespToReqTran: removing unneeded z9hG4bK56C8ADB0 from via branch list Apr 9 10:11:34.629: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x7FFDB2D061F8) counter, current msg->refCount = 2 Apr 9 10:11:34.629: //556197/000000000000/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 500 Internal Server Error Via: SIP/2.0/UDP 10.50.66.1:5060;branch=z9hG4bK56C8ADB0 From: ;tag=7AA29BC4-663 To: ;tag=7AA29DBC-223A Date: Mon, 09 Apr 2018 08:11:34 GMT Call-ID: FFFFFFFF993B71AD-39D411E8-FFFFFFFF9327AD25-FFFFFFFFDD7BDD2E Server: Cisco-SIPGateway/IOS-15.4.3.S4 Timestamp: 1523261494 CSeq: 725 REGISTER Content-Length: 0 Apr 9 10:11:34.629: //556197/000000000000/SIP/Info/verbose/1024/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX Apr 9 10:11:34.629: //-1/xxxxxxxxxxxx/SIP/Info/info/262144/sipSPIDecrementOverloadCount: Count:Local 0 Global 0 Apr 9 10:11:34.629: //556197/000000000000/SIP/Error/ccsip_api_register_result_ind: Message Code Class 5xx Method Code 100 received for REGISTER Apr 9 10:11:34.629: //-1/xxxxxxxxxxxx/SIP/Info/notify/262144/ccsip_register_reset_dns_cache: CCSIP_REGISTER:: registrar 0 DNS resolved addr reset Apr 9 10:11:34.629: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x7FFDB2D061F8) counter, current msg->refCount = 1 Apr 9 10:11:34.629: //556197/000000000000/SIP/Info/notify/262144/sipSPIRegPthruProcessResponse: Processing response w/ resp code == 500 Apr 9 10:11:34.629: //-1/xxxxxxxxxxxx/SIP/Info/verbose/262144/sipSPIGetRPCBFromRCB: Retreiving RCB [0x7FFDB20B0A18] from RPCB [0x0] Apr 9 10:11:34.629: //556197/000000000000/SIP/Info/critical/262144/sipSPIRegPthruProcessResponse: Error NO RPCB Apr 9 10:11:34.629: //-1/xxxxxxxxxxxx/SIP/Info/info/2048/ccsipRegisterStartRCBTimer: Starting timer for pattern . for 180 seconds Apr 9 10:11:34.629: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[567305] removed. Apr 9 10:11:34.629: //556197/000000000000/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x7FFDA8AFBAB8 key=FFFFFFFF993B71AD-39D411E8-FFFFFFFF9327AD25-FFFFFFFFDD7BDD2E Apr 9 10:11:34.629: //556197/000000000000/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Apr 9 10:11:34.629: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x7FFDA0BDA6A0, addr=10.50.66.1, port=5060, local_addr=10.50.66.1, unregistering context=0x7FFDA8AFBAB8 Apr 9 10:11:34.629: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x7FFDA8AFBAB8 from the connection=0x7FFDA0F7D340 context list Apr 9 10:11:34.629: //556197/000000000000/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Apr 9 10:11:34.629: //556197/000000000000/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer Apr 9 10:11:34.629: //556197/000000000000/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x7FFDA8AFBAB8 Apr 9 10:11:34.629: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[567305]