User Access Verification Password: CME>ena Password: CME#termi moni CME#de Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Info/verbose/512/ccsip_get_vrf_from_sip_bind: vrfid 0 for tag 0, sip_vrfid 0, voice_vrfid 0 Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x22A9C7A8) with key=[177723] to table Sep 3 19:46:46.472: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init: Sep 3 19:46:46.472: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init: Sep 3 19:46:46.472: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised.. Sep 3 19:46:46.472: //-1/000000000000/SIP/Info/notify/262144/ccsipRegisterSetTargetInfo: p2p mode with Registrar Server = ipv4:192.168.1.2 Sep 3 19:46:46.472: //-1/000000000000/SIP/Info/verbose/262144/ccsipRegisterSetTargetInfo: Parsing The Registrar Address Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Info/verbose/5120/sipSPIGetOutboundHostAndDestHostPrivate: CCSIP: target_host : 192.168.1.2 target_port : 5060 Sep 3 19:46:46.472: //-1/000000000000/SIP/Info/verbose/5120/sipSPIValidateAndCopyOutboundHost: CCSIP: copy target_host to outbound_host Sep 3 19:46:46.472: //-1/000000000000/SIP/Info/critical/8192/sipSPIOutboundProxyReuse: Do not reuse Outbound Proxy IP adress and Port Sep 3 19:46:46.472: //-1/000000000000/SIP/Info/verbose/262144/ccsip_spi_outgoing_register: ccb's vrfid is set to 0 Sep 3 19:46:46.472: //-1/000000000000/SIP/State/sipSPIChangeState: 0x22A9C7A8 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Sep 3 19:46:46.472: //-1bu/000000000000/SIP/Info/verbose/6144/ccsip_spi_registrar_add_expires_header: Inside ccsip_spi_registrar_add_expires_header for Expires Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_OUTBOUND_REGISTER Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Info/info/262144/sipSPIIncrementOverloadCount: Local 1 Global 1 Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 40 Sep 3 19:46:46.472: //-1/000000000000/SIP/Info/verbose/262144/act_idle_outgoing_register: In act_idle_outgoing_register Sep 3 19:46:46.472: //92085/000000000000/SIP/Info/info/262144/act_idle_outgoing_register: Send REGISTER to 192.168.1.2:5060 Sep 3 19:46:46.472: //92085/000000000000/SIP/Info/verbose/4096/sipSPIUaddCcbToUACTable: ****Adding to UAC table.0x22A9C7A8 96A8DEC1-8A6111E7-8011CBC6-A9D31E24 Sep 3 19:46:46.472: //92085/000000000000/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x22A9C7A8 key=96A8DEC1-8A6111E7-8011CBC6-A9D31E24 balance 1 Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Info/verbose/512/ccsip_get_vrf_from_sip_bind: vrfid 0 for tag 0, sip_vrfid 0, voice_vrfid 0 Sep 3 19:46:46.472: //92085/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 3 19:46:46.472: //92085/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: ip_best_local_address 192.168.1.2 for SIP Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 192.168.1.2 Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3A047F80 with refCount = 1 Sep 3 19:46:46.472: //92085/000000000000/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 8 event Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT Sep 3 19:46:46.472: //92085/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:46:46.472: //92085/000000000000/SIP/Info/info/4096/sipSPISendRegister: Associated container=0x239FE428 to Register Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Sep 3 19:46:46.472: //92085/000000000000/SIP/Transport/sipSPISendRegister: Sending REGISTER to the transport layer ccs Sep 3 19:46:46.472: //92085/000000000000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE Sep 3 19:46:46.472: //92085/000000000000/SIP/Transport/sipSPITransportSendMessage: msg=0x3A047F80, addr=192.168.1.2, port=5060, sentBy_port=0, local_addr=, is_req=1, transport=1, switch=0, callBack=0x35A1AC88 Sep 3 19:46:46.472: //92085/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:46:46.472: //92085/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:46:46.472: //92085/000000000000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:192.168.1.2, rport:5060 with laddr: Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x22A9C7A8 with connection=0x2247C3E4 context list Sep 3 19:46:46.472: //92085/000000000000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x3A047F80 Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x3A047F80, addr=192.168.1.2, port=5060, local_addr=, connId=2 vrfid=0 for UDP Sep 3 19:46:46.472: //92085/000000000000/SIP/State/sipSPIChangeState: 0x22A9C7A8 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) Sep 3 19:46:46.472: //92085/000000000000/SIP/State/sipSPIChangeState: 0x22A9C7A8 : State change from (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) Sep 3 19:46:46.472: //92085/000000000000/SIP/Msg/ccsipDisplayMsg: Sent: REGISTER sip:192.168.1.2:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bKC891C69 From: ;tag=256D9544-EBD To: Date: Sun, 03 Sep 2017 19:46:46 GMT Call-ID: 96A8DEC1-8A6111E7-8011CBC6-A9D31E24 User-Agent: Cisco-SIPGateway/IOS-15.7.3.M Max-Forwards: 70 Timestamp: 1504468006 CSeq: 3490 REGISTER Contact: Expires: 3600 Supported: path Content-Length: 0 Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3A047F80 Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3A047F80 with refCount = 1 Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3F01EE68 with refCount = 1 Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.1.2]:59870, local_address:[ - ] Sep 3 19:46:46.472: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3A047F80 Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: REGISTER sip:192.168.1.2:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bKC891C69 From: ;tag=256D9544-EBD To: Date: Sun, 03 Sep 2017 19:46:46 GMT Call-ID: 96A8DEC1-8A6111E7-8011CBC6-A9D31E24 User-Agent: Cisco-SIPGateway/IOS-15.7.3.M Max-Forwards: 70 Timestamp: 1504468006 CSeq: 3490 REGISTER Contact: Expires: 3600 Supported: path Content-Length: 0 Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Sep 3 19:46:46.476: //92085/000000000000/SIP/Info/info/4096/sipSPICheckFromToRequest: Trying with child CCB 0x0 index 0 curr_child 0 Sep 3 19:46:46.476: //92085/000000000000/SIP/Error/sipSPICheckFromToRequest: Failed FROM/TO Request check - IGNORE IF HAIRPIN CALL old_from: ;tag=256D9544-EBD old_to: new_from: ;tag=256D9544-EBD new_to: Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x22B2AA98) with key=[177724] to table Sep 3 19:46:46.476: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init: Sep 3 19:46:46.476: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init: Sep 3 19:46:46.476: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised.. Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 192.168.1.2,Port 5060, Transport 1, SentBy Port 5060vrfid 0 Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Info/verbose/512/ccsip_get_vrf_from_sip_bind: vrfid 0 for tag 0, sip_vrfid 0, voice_vrfid 0 Sep 3 19:46:46.476: //-1/000000000000/SIP/Info/info/8192/ripesolve_sig_ip_address_to_bind: VRF id = 0 Sep 3 19:46:46.476: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: ip_best_local_address 192.168.1.2 for SIP Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 192.168.1.2 Sep 3 19:46:46.476: //-1/741C93B8B34A/SIP/State/sipSPIChangeState: 0x22B2AA98 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 192.168.1.2,Port 59870, Transport 1, SentBy Port 5060vrfid 0 Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 192.168.1.2,Port 59870, Transport 1, SentBy Port 5060vrfid 0 Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x3F01EE68) counter, current msg->refCount = 2 Sep 3 19:46:46.476: //-1/741C93B8B34A/SIP/Info/verbose/4096/sipSPIAssignCcbLastRequest: Current ccb(0x22B2AA98)->last_request = 0x3F01EE68, refCount = 2 Sep 3 19:46:46.476: //-1/741C93B8B34A/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x22B2AA98 key=96A8DEC1-8A6111E7-8011CBC6-A9D31E24900*256D9544-EBD balance 0 Sep 3 19:46:46.476: //92086/741C93B8B34A/SIP/Event/sact_idle_new_message_register: ccsip_api_register_ind return value : SIP_SUCCESS Sep 3 19:46:46.476: //92086/741C93B8B34A/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable: Adding call id 167B6 to table Sep 3 19:46:46.476: //92086/741C93B8B34A/SIP/State/sipSPIChangeState: 0x22B2AA98 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE) Sep 3 19:46:46.476: //92086/741C93B8B34A/SIP/Info/notify/262144/ccsip_register_process_incoming_register: CCSIP_REGISTER:: REGISTER request Sep 3 19:46:46.476: //92086/741C93B8B34A/SIP/Info/notify/262144/ccsip_spi_register_incoming_registration: registration expires timer max is 3600 and min is 60 Sep 3 19:46:46.476: //92086/741C93B8B34A/SIP/Info/notify/262144/ccsip_spi_registration_failed: Sending Register Response 482 Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_REGISTER_RESP Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 41 Sep 3 19:46:46.476: //92086/741C93B8B34A/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 13 event Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3A047F80 with refCount = 1 Sep 3 19:46:46.476: //92086/741C93B8B34A/SIP/Info/info/4096/sipSPISendResponse: Associated container=0x239FEFD8 to REGISTER Response 482 Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Sep 3 19:46:46.476: //92086/741C93B8B34A/SIP/Transport/sipSPISendResponse: Sending INFO Response to the transport layer Sep 3 19:46:46.476: //92086/741C93B8B34A/SIP/Transport/sipSPITransportSendMessage: msg=0x3A047F80, addr=192.168.1.2, port=59870, sentBy_port=5060, local_addr=, is_req=0, transport=1, switch=0, callBack=0x35A1ABC0 Sep 3 19:46:46.476: //92086/741C93B8B34A/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:46:46.476: //92086/741C93B8B34A/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:46:46.476: //92086/741C93B8B34A/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Sep 3 19:46:46.476: //92086/741C93B8B34A/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x3A047F80 to default port=5060 Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:192.168.1.2, rport:5060 with laddr: Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x22B2AA98 with connection=0x2247C3E4 context list Sep 3 19:46:46.476: //92086/741C93B8B34A/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x3A047F80 Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x3A047F80, addr=192.168.1.2, port=5060, local_addr=, connId=2 vrfid=0 for UDP Sep 3 19:46:46.476: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x3F01EE68) counter, current msg->refCount = 1 Sep 3 19:46:46.476: //92086/741C93B8B34A/SIP/State/sipSPIChangeState: 0x22B2AA98 : State change from (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Sep 3 19:46:46.480: //92086/741C93B8B34A/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 482 Loop Detected Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bKC891C69 From: ;tag=256D9544-EBD To: ;tag=256D9548-22D3 Date: Sun, 03 Sep 2017 19:46:46 GMT Call-ID: 96A8DEC1-8A6111E7-8011CBC6-A9D31E24 Server: Cisco-SIPGateway/IOS-15.7.3.M Timestamp: 1504468006 CSeq: 3490 REGISTER Content-Length: 0 Sep 3 19:46:46.480: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3A047F80 Sep 3 19:46:46.480: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3A047F80 with refCount = 1 Sep 3 19:46:46.480: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3A06AAB8 with refCount = 1 Sep 3 19:46:46.480: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.1.2]:59870, local_address:[ - ] Sep 3 19:46:46.480: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3A047F80 Sep 3 19:46:46.480: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Sep 3 19:46:46.480: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Sep 3 19:46:46.480: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Sep 3 19:46:46.480: //92085/000000000000/SIP/Info/info/1024/sipSPIMatchRespToReqTran: removing unneeded z9hG4bKC891C69 from via branch list Sep 3 19:46:46.480: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x3A06AAB8) counter, current msg->refCount = 2 Sep 3 19:46:46.480: //92085/000000000000/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 482 Loop Detected Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bKC891C69 From: ;tag=256D9544-EBD To: ;tag=256D9548-22D3 Date: Sun, 03 Sep 2017 19:46:46 GMT Call-ID: 96A8DEC1-8A6111E7-8011CBC6-A9D31E24 Server: Cisco-SIPGateway/IOS-15.7.3.M Timestamp: 1504468006 CSeq: 3490 REGISTER Content-Length: 0 Sep 3 19:46:46.480: //92085/000000000000/SIP/Info/verbose/1024/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX Sep 3 19:46:46.480: //-1/xxxxxxxxxxxx/SIP/Info/info/262144/sipSPIDecrementOverloadCount: Count:Local 0 Global 0 Sep 3 19:46:46.480: //92085/000000000000/SIP/Error/ccsip_api_register_result_ind: Message Code Class 4xx Method Code 100 received for REGISTER Sep 3 19:46:46.480: //-1/xxxxxxxxxxxx/SIP/Info/notify/262144/ccsip_register_reset_dns_cache: CCSIP_REGISTER:: registrar 0 DNS resolved addr reset Sep 3 19:46:46.480: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x3A06AAB8) counter, current msg->refCount = 1 Sep 3 19:46:46.480: //92085/000000000000/SIP/Info/notify/262144/sipSPIRegPthruProcessResponse: Processing response w/ resp code == 482 Sep 3 19:46:46.480: //-1/xxxxxxxxxxxx/SIP/Info/verbose/262144/sipSPIGetRPCBFromRCB: Retreiving RCB [0x22D45E88] from RPCB [0x0] Sep 3 19:46:46.480: //92085/000000000000/SIP/Info/critical/262144/sipSPIRegPthruProcessResponse: Error NO RPCB Sep 3 19:46:46.480: //-1/xxxxxxxxxxxx/SIP/Info/info/2048/ccsipRegisterStartRCBTimer: Starting timer for pattern 900* for 180 seconds Sep 3 19:46:46.480: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[177723] removed. Sep 3 19:46:46.480: //92085/000000000000/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x22A9C7A8 key=96A8DEC1-8A6111E7-8011CBC6-A9D31E24 Sep 3 19:46:46.480: //92085/000000000000/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Sep 3 19:46:46.480: //92085/000000000000/SIP/Error/sipSPIFlushDeferredQueue: Invalid deferredQueue Sep 3 19:46:46.480: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x2247BAEC, addr=192.168.1.2, port=5060, local_addr=, unregistering context=0x22A9C7A8 Sep 3 19:46:46.480: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x22A9C7A8 from the connection=0x2247C3E4 context list Sep 3 19:46:46.480: //92085/000000000000/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Sep 3 19:46:46.480: //92085/000000000000/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer Sep 3 19:46:46.480: //92085/000000000000/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x22A9C7A8 Sep 3 19:46:46.480: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[177723] Sep 3 19:46:46.480: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3A06AAB8 Sep 3 19:46:46.800: //92078/6128E472B346/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 167AE Sep 3 19:46:46.800: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[177716] removed. Sep 3 19:46:46.800: //92078/6128E472B346/SIP/I allnfo/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x22ABCCB0 key=43FD743E-8A6711E7-8238CBC6-A9D31E242001256D1910-1AC4 Sep 3 19:46:46.800: //92078/6128E472B346/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Sep 3 19:46:46.800: //92078/6128E472B346/SIP/Error/sipSPIFlushDeferredQueue: Invalid deferredQueue Sep 3 19:46:46.800: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x2247BAEC, addr=192.168.1.2, port=5060, local_addr=, unregistering context=0x22ABCCB0 Sep 3 19:46:46.800: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x22ABCCB0 from the connection=0x2247C3E4 context list Sep 3 19:46:46.800: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x23C3FF80 Sep 3 19:46:46.800: //92078/6128E472B346/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Sep 3 19:46:46.800: //92078/6128E472B346/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer Sep 3 19:46:46.800: //92078/6128E472B346/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x22ABCCB0 Sep 3 19:46:48.568: //92080/62485DF1B347/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 167B0 Sep 3 19:46:48.568: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[177718] removed. Sep 3 19:46:48.568: //92080/62485DF1B347/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x22B44838 key=846BADCE-8A6111E7-8002CBC6-A9D31E241050256D206C-1C9A Sep 3 19:46:48.568: //92080/62485DF1B347/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Sep 3 19:46:48.568: //92080/62485DF1B347/SIP/Error/sipSPIFlushDeferredQueue: Invalid deferredQueue Sep 3 19:46:48.568: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x2247BAEC, addr=192.168.1.2, port=5060, local_addr=, unregistering context=0x22B44838 Sep 3 19:46:48.568: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x22B44838 from the connection=0x2247C3E4 context list Sep 3 19:46:48.568: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x23C46DF4 Sep 3 19:46:48.568: //92080/62485DF1B347/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Sep 3 19:46:48.568: //92080/62485DF1B347/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer Sep 3 19:46:48.568: //92080/62485DF1B347/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x22B44838 Sep 3 19:46:51.440: //92082/63EC4A66B348/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 167B2 Sep 3 19:46:51.440: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[177720] removed. Sep 3 19:46:51.440: //92082/63EC4A66B348/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x22AAFDE0 key=1B8C34C-8A6C11E7-83ECCBC6-A9D31E242007256D2B2C-1DE6 Sep 3 19:46:51.440: //92082/63EC4A66B348/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Sep 3 19:46:51.440: //92082/63EC4A66B348/SIP/Error/sipSPIFlushDeferredQueue: Invalid deferredQueue Sep 3 19:46:51.440: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x2247BAEC, addr=192.168.1.2, port=5060, local_addr=, unregistering context=0x22AAFDE0 Sep 3 19:46:51.440: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x22AAFDE0 from the connection=0x2247C3E4 context list Sep 3 19:46:51.440: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3FA2C960 Sep 3 19:46:51.440: //92082/63EC4A66B348/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed This may severely impact system performance. Continue? [confirm] Sep 3 19:46:51.440: //92082/63EC4A66B348/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer Sep 3 19:46:51.440: //92082/63EC4A66B348/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x22AAFDE0 Sep 3 19:46:53.396: //92084/6529AC4FB349/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 167B4 Sep 3 19:46:53.396: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[177722] removed. Sep 3 19:46:53.396: //92084/6529AC4FB349/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x22B3E0D0 key=8B64F58B-8A6111E7-8007CBC6-A9D31E242006256D334C-17B1 Sep 3 19:46:53.396: //92084/6529AC4FB349/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Sep 3 19:46:53.396: //92084/6529AC4FB349/SIP/Error/sipSPIFlushDeferredQueue: Invalid deferredQueue Sep 3 19:46:53.396: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x2247BAEC, addr=192.168.1.2, port=5060, local_addr=, unregistering context=0x22B3E0D0 Sep 3 19:46:53.396: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x22B3E0D0 from the connection=0x2247C3E4 context list Sep 3 19:46:53.396: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x23BE2E58 Sep 3 19:46:53.396: //92084/6529AC4FB349/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Sep 3 19:46:53.396: //92084/6529AC4FB349/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer Sep 3 19:46:53.396: //92084/6529AC4FB349/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x22B3E0D0 All SIP Call tracing is enabled CME# CME# CME# CME# CME# CME# CME# CME# CME# CME# CME# Sep 3 19:47:18.476: //92086/741C93B8B34A/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 167B6 Sep 3 19:47:18.476: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[177724] removed. Sep 3 19:47:18.476: //92086/741C93B8B34A/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x22B2AA98 key=96A8DEC1-8A6111E7-8011CBC6-A9D31E24900*256D9544-EBD Sep 3 19:47:18.476: //92086/741C93B8B34A/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Sep 3 19:47:18.476: //92086/741C93B8B34A/SIP/Error/sipSPIFlushDeferredQueue: Invalid deferredQueue Sep 3 19:47:18.476: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x2247BAEC, addr=192.168.1.2, port=5060, local_addr=, unregistering context=0x22B2AA98 Sep 3 19:47:18.476: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x22B2AA98 from the connection=0x2247C3E4 context list Sep 3 19:47:18.476: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3F01EE68 Sep 3 19:47:18.476: //92086/741C93B8B34A/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Sep 3 19:47:18.476: //92086/741C93B8B34A/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer Sep 3 19:47:18.476: //92086/741C93B8B34A/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x22B2AA98 Sep 3 19:47:22.284: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceHandleConnAgeing: Holder=0x3F140920 Connection=0x2247C3E4, addr=192.168.1.2, port=5060, connid=2 has been REFRESHED Sep 3 19:47:22.284: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetAgeingTimer: Aging timer initiated for holder=0x3F140920,addr=192.168.1.2 CME# CME# CME# CME# CME# CME# CME# CME# Sep 3 19:47:35.572: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3F01EE68 with refCount = 1 Sep 3 19:47:35.572: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x23C46DF4 with refCount = 1 Sep 3 19:47:35.572: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.1.30]:5060, local_address:[ - ] Sep 3 19:47:35.572: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3F01EE68 Sep 3 19:47:35.572: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Sep 3 19:47:35.572: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Sep 3 19:47:35.572: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: REGISTER sip:192.168.1.2 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.30:5060;branch=z9hG4bK-ea584132 From: "5011" ;tag=12887da2fe650436o0 To: "5011" Call-ID: 358f9193-fdb184d@192.168.1.30 CSeq: 45681 REGISTER Max-Forwards: 70 Contact: "5011" ;expires=600 User-Agent: Cisco/SPA525G2-7.5.5a Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE Supported: replaces Sep 3 19:47:35.572: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Sep 3 19:47:35.572: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIFindRegisterCcb: *****CCB NOT found in UAS Request table. ccb=0x0 Sep 3 19:47:35.572: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x22B2AA98) with key=[177725] to table Sep 3 19:47:35.572: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init: Sep 3 19:47:35.572: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init: Sep 3 19:47:35.572: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised.. Sep 3 19:47:35.572: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 192.168.1.30,Port 5060, Transport 1, SentBy Port 5060vrfid 0 Sep 3 19:47:35.572: //-1/xxxxxxxxxxxx/SIP/Info/verbose/512/ccsip_get_vrf_from_sip_bind: vrfid 0 for tag 0, sip_vrfid 0, voice_vrfid 0 Sep 3 19:47:35.572: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 3 19:47:35.572: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 3 19:47:35.572: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: ip_best_local_address 192.168.1.2 for SIP Sep 3 19:47:35.572: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 192.168.1.2 Sep 3 19:47:35.572: //-1/916007C1B34B/SIP/State/sipSPIChangeState: 0x22B2AA98 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Sep 3 19:47:35.572: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 192.168.1.30,Port 5060, Transport 1, SentBy Port 5060vrfid 0 Sep 3 19:47:35.572: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT Sep 3 19:47:35.572: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 192.168.1.30,Port 5060, Transport 1, SentBy Port 5060vrfid 0 Sep 3 19:47:35.572: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x23C46DF4) counter, current msg->refCount = 2 Sep 3 19:47:35.572: //-1/916007C1B34B/SIP/Info/verbose/4096/sipSPIAssignCcbLastRequest: Current ccb(0x22B2AA98)->last_request = 0x23C46DF4, refCount = 2 Sep 3 19:47:35.572: //-1/916007C1B34B/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x22B2AA98 key=358f9193-fdb184d@192.168.1.30501112887da2fe650436o0 balance 1 Sep 3 19:47:35.572: //92087/916007C1B34B/SIP/Event/sact_idle_new_message_register: ccsip_api_register_ind return value : SIP_SUCCESS Sep 3 19:47:35.572: //92087/916007C1B34B/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable: Adding call id 167B7 to table Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/State/sipSPIChangeState: 0x22B2AA98 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE) Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/notify/262144/ccsip_register_process_incoming_register: CCSIP_REGISTER:: REGISTER request Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/notify/262144/ccsip_spi_register_incoming_registration: registration expires timer max is 3600 and min is 60 Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Error/ccsip_reg_search_call_id_table: No entry found in sipCallID Table Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Info/info/262144/ccsip_process_registration_passthrough: RCB Pointer : [0x0] Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/verbose/1024/sipSPIGetViaHostInURLFormat: VIA URL:sip:192.168.1.30:5060, Host:192.168.1.30 Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/info/2048/sipSPIGetRegisterConfig: Peer-Tag = 0, Reg-Pthru = Disable Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/verbose/10240/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0 Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/verbose/2048/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0 Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/notify/10240/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/critical/262144/ccsip_process_registration_passthrough: Register not for passthrough, Try CME Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/info/262144/ccsip_process_registration_passthrough: Resetting peer_tag Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/info/262144/ccsip_spi_register_incoming_registration: Register for CME case Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_spi_register_get_rcb: Getting New RCB [0x22D5E4C4] Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/verbose/262144/ccsip_spi_update_cc_callid: ccCallId for RCB is 92088 Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Error/sipSPI_validate_own_ip_addr: ReqLine IP addr does not match with host IP addr Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/info/65536/ccsip_sipline_set_vrf: Phone number 5011 from contact passed to this function Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Info/info/65536/ccsip_sipline_set_vrf: Obtained phone tag (0) from Dial-peer Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Info/info/65536/ccsip_sipline_set_vrf: Getting phone index for phone 5011 Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Info/verbose/512/ccsip_get_vrf_from_sip_bind: vrfid 0 for tag 0, sip_vrfid 0, voice_vrfid 0 Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: ip_best_local_address 192.168.1.2 for SIP Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 192.168.1.2 Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Error/ccsip_spi_register_incoming_registration: Registration Authorization failed with authorization header= Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/notify/262144/ccsip_spi_registration_failed: Sending Challenge 401/407 response Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/notify/262144/ccsip_spi_registration_failed: Sending Register Response 401 Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_REGISTER_RESP Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/verbose/262144/ccsipGetCCBFromRCB: Retrived CCB pointer [0x22B2AA98] Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Info/verbose/262144/sipSPIFreePthruDataFromRPCBorRCB: RCB =[0x22D5E4C4].. RPCB =[0x0] Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Info/verbose/9216/sipSPIPassThruHdrContainerFreeHelper: Data -->[0x0] Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Error/sipSPI_ipip_PassthruContentContainerFreeHelper: Null ContentQ - Exit Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Error/ccsip_rpcb_search_cc_call_id_table: No entry found in ccCallID Table Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_spi_register_free_rcb: Freeing rcb [0x22D5E4C4] Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 41 Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 13 event Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3F01EE68 with refCount = 1 Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/info/4096/sipSPISendResponse: Associated container=0x239FDCF0 to REGISTER Response 401 Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Transport/sipSPISendResponse: Sending INFO Response to the transport layer Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Transport/sipSPITransportSendMessage: msg=0x3F01EE68, addr=192.168.1.30, port=5060, sentBy_port=5060, local_addr=, is_req=0, transport=1, switch=0, callBack=0x35A1ABC0 Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x3F01EE68 to default port=5060 Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:192.168.1.30, rport:5060 with laddr: Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x22B2AA98 with connection=0x2247CC04 context list Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x3F01EE68 Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x3F01EE68, addr=192.168.1.30, port=5060, local_addr=, connId=3 vrfid=0 for UDP Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x23C46DF4) counter, current msg->refCount = 1 Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/State/sipSPIChangeState: 0x22B2AA98 : State change from (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Sep 3 19:47:35.576: //92087/916007C1B34B/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.1.30:5060;branch=z9hG4bK-ea584132 From: "5011" ;tag=12887da2fe650436o0 To: "5011" ;tag=256E5510-369 Date: Sun, 03 Sep 2017 19:47:35 GMT Call-ID: 358f9193-fdb184d@192.168.1.30 Server: Cisco-SIPGateway/IOS-15.7.3.M CSeq: 45681 REGISTER WWW-Authenticate: Digest realm="",nonce="8A84F2ED03BE3BB5",algorithm=MD5,qop="auth" Content-Length: 0 Sep 3 19:47:35.576: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3F01EE68 Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3F01EE68 with refCount = 1 Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3A016664 with refCount = 1 Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.1.30]:5060, local_address:[ - ] Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3F01EE68 Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: REGISTER sip:192.168.1.2 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.30:5060;branch=z9hG4bK-d892e684 From: "5011" ;tag=12887da2fe650436o0 To: "5011" Call-ID: 358f9193-fdb184d@192.168.1.30 CSeq: 45682 REGISTER Max-Forwards: 70 Authorization: Digest username="5011",realm="",nonce="8A84F2ED03BE3BB5",uri="sip:192.168.1.2",algorithm=MD5,response="02cca8b466d503feca047636c16ad836",qop=auth,nc=00000001,cnonce="89992089" Contact: "5011" ;expires=600 User-Agent: Cisco/SPA525G2-7.5.5a Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE Supported: replaces Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Sep 3 19:47:35.604: //92087/916007C1B34B/SIP/Info/verbose/4096/sipSPIFindRegisterCcb: *****CCB found in UAS Request table. ccb=0x22B2AA98 Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x3A016664) counter, current msg->refCount = 2 Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 192.168.1.30,Port 5060, Transport 1, SentBy Port 5060vrfid 0 Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 192.168.1.30,Port 5060, Transport 1, SentBy Port 5060vrfid 0 Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x3A016664) counter, current msg->refCount = 3 Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x3A016664) counter, current msg->refCount = 2 Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x3A016664) counter, current msg->refCount = 3 Sep 3 19:47:35.604: //92087/916007C1B34B/SIP/Info/verbose/4096/sipSPIAssignCcbLastRequest: Current ccb(0x22B2AA98)->last_request = 0x3A016664, refCount = 3 Sep 3 19:47:35.604: //92087/916007C1B34B/SIP/Event/sact_idle_new_message_register: ccsip_api_register_ind return value : SIP_SUCCESS Sep 3 19:47:35.604: //92087/916007C1B34B/SIP/State/sipSPIChangeState: 0x22B2AA98 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE) Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x3A016664) counter, current msg->refCount = 2 Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x23C46DF4 Sep 3 19:47:35.604: //92087/916007C1B34B/SIP/Info/notify/262144/ccsip_register_process_incoming_register: CCSIP_REGISTER:: REGISTER request Sep 3 19:47:35.604: //92087/916007C1B34B/SIP/Info/notify/262144/ccsip_spi_register_incoming_registration: registration expires timer max is 3600 and min is 60 Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Error/ccsip_reg_search_call_id_table: No entry found in sipCallID Table Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Info/info/262144/ccsip_process_registration_passthrough: RCB Pointer : [0x0] Sep 3 19:47:35.604: //92087/916007C1B34B/SIP/Info/verbose/1024/sipSPIGetViaHostInURLFormat: VIA URL:sip:192.168.1.30:5060, Host:192.168.1.30 Sep 3 19:47:35.604: //92087/916007C1B34B/SIP/Info/info/2048/sipSPIGetRegisterConfig: Peer-Tag = 0, Reg-Pthru = Disable Sep 3 19:47:35.604: //92087/916007C1B34B/SIP/Info/verbose/10240/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0 Sep 3 19:47:35.604: //92087/916007C1B34B/SIP/Info/verbose/2048/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0 Sep 3 19:47:35.604: //92087/916007C1B34B/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:47:35.604: //92087/916007C1B34B/SIP/Info/notify/10240/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled Sep 3 19:47:35.604: //92087/916007C1B34B/SIP/Info/critical/262144/ccsip_process_registration_passthrough: Register not for passthrough, Try CME Sep 3 19:47:35.604: //92087/916007C1B34B/SIP/Info/info/262144/ccsip_process_registration_passthrough: Resetting peer_tag Sep 3 19:47:35.604: //92087/916007C1B34B/SIP/Info/info/262144/ccsip_spi_register_incoming_registration: Register for CME case Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_spi_register_get_rcb: Getting New RCB [0x3FB9AEE0] Sep 3 19:47:35.604: //92087/916007C1B34B/SIP/Info/verbose/262144/ccsip_spi_update_cc_callid: ccCallId for RCB is 92089 Sep 3 19:47:35.604: //-1/xxxxxxxxxxxx/SIP/Error/sipSPI_validate_own_ip_addr: ReqLine IP addr does not match with host IP addr Sep 3 19:47:35.608: //92087/916007C1B34B/SIP/Info/info/65536/ccsip_sipline_set_vrf: Phone number 5011 from contact passed to this function Sep 3 19:47:35.608: //-1/xxxxxxxxxxxx/SIP/Info/info/65536/ccsip_sipline_set_vrf: Obtained phone tag (0) from Dial-peer Sep 3 19:47:35.608: //-1/xxxxxxxxxxxx/SIP/Info/info/65536/ccsip_sipline_set_vrf: Getting phone index for phone 5011 Sep 3 19:47:35.608: //-1/xxxxxxxxxxxx/SIP/Info/verbose/512/ccsip_get_vrf_from_sip_bind: vrfid 0 for tag 0, sip_vrfid 0, voice_vrfid 0 Sep 3 19:47:35.608: //92087/916007C1B34B/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 3 19:47:35.608: //92087/916007C1B34B/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 3 19:47:35.608: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: ip_best_local_address 192.168.1.2 for SIP Sep 3 19:47:35.608: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 192.168.1.2 Sep 3 19:47:35.608: //92087/916007C1B34B/SIP/Error/ccsip_spi_register_incoming_registration: Registration Authorization failed with authorization header=Digest username="5011",realm="",nonce="8A84F2ED03BE3BB5",uri="sip:192.168.1.2",algorithm=MD5,response="02cca8b466d503feca047636c16ad836",qop=auth,nc=00000001,cnonce="89992089" Sep 3 19:47:35.608: //92087/916007C1B34B/SIP/Info/notify/262144/ccsip_spi_registration_failed: Sending Challenge 401/407 response Sep 3 19:47:35.608: //92087/916007C1B34B/SIP/Info/notify/262144/ccsip_spi_registration_failed: Sending Register Response 401 Sep 3 19:47:35.608: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_REGISTER_RESP Sep 3 19:47:35.608: //92087/916007C1B34B/SIP/Info/verbose/262144/ccsipGetCCBFromRCB: Retrived CCB pointer [0x22B2AA98] Sep 3 19:47:35.608: //-1/xxxxxxxxxxxx/SIP/Info/verbose/262144/sipSPIFreePthruDataFromRPCBorRCB: RCB =[0x3FB9AEE0].. RPCB =[0x0] Sep 3 19:47:35.608: //-1/xxxxxxxxxxxx/SIP/Info/verbose/9216/sipSPIPassThruHdrContainerFreeHelper: Data -->[0x0] Sep 3 19:47:35.608: //-1/xxxxxxxxxxxx/SIP/Error/sipSPI_ipip_PassthruContentContainerFreeHelper: Null ContentQ - Exit Sep 3 19:47:35.608: //-1/xxxxxxxxxxxx/SIP/Error/ccsip_rpcb_search_cc_call_id_table: No entry found in ccCallID Table Sep 3 19:47:35.608: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_spi_register_free_rcb: Freeing rcb [0x3FB9AEE0] Sep 3 19:47:35.608: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 41 Sep 3 19:47:35.608: //92087/916007C1B34B/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 13 event Sep 3 19:47:35.608: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x23C46DF4 with refCount = 1 Sep 3 19:47:35.608: //92087/916007C1B34B/SIP/Info/info/4096/sipSPISendResponse: Associated container=0x239FE218 to REGISTER Response 401 Sep 3 19:47:35.608: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Sep 3 19:47:35.608: //92087/916007C1B34B/SIP/Transport/sipSPISendResponse: Sending INFO Response to the transport layer Sep 3 19:47:35.608: //92087/916007C1B34B/SIP/Transport/sipSPITransportSendMessage: msg=0x23C46DF4, addr=192.168.1.30, port=5060, sentBy_port=5060, local_addr=, is_req=0, transport=1, switch=0, callBack=0x35A1ABC0 Sep 3 19:47:35.608: //92087/916007C1B34B/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:47:35.608: //92087/916007C1B34B/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:47:35.608: //92087/916007C1B34B/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Sep 3 19:47:35.608: //92087/916007C1B34B/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x23C46DF4 to default port=5060 Sep 3 19:47:35.608: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:192.168.1.30, rport:5060 with laddr: Sep 3 19:47:35.608: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: gcb=0x22B2AA98 is already on connection=0x2247CC04 context_list Sep 3 19:47:35.608: //92087/916007C1B34B/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x23C46DF4 Sep 3 19:47:35.608: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x23C46DF4, addr=192.168.1.30, port=5060, local_addr=, connId=3 vrfid=0 for UDP Sep 3 19:47:35.608: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x3A016664) counter, current msg->refCount = 1 Sep 3 19:47:35.608: //92087/916007C1B34B/SIP/State/sipSPIChangeState: 0x22B2AA98 : State change from (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Sep 3 19:47:35.608: //92087/916007C1B34B/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.1.30:5060;branch=z9hG4bK-d892e684 From: "5011" ;tag=12887da2fe650436o0 To: "5011" ;tag=256E5510-369 Date: Sun, 03 Sep 2017 19:47:35 GMT Call-ID: 358f9193-fdb184d@192.168.1.30 Server: Cisco-SIPGateway/IOS-15.7.3.M CSeq: 45682 REGISTER WWW-Authenticate: Digest realm="",nonce="8A84F2ED03BE3BB5",algorithm=MD5,qop="auth" Content-Length: 0 Sep 3 19:47:35.608: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x23C46DF4 Sep 3 19:47:35.644: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x23C46DF4 with refCount = 1 Sep 3 19:47:35.644: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3F01EE68 with refCount = 1 Sep 3 19:47:35.644: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.1.30]:5060, local_address:[ - ] Sep 3 19:47:35.644: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x23C46DF4 Sep 3 19:47:35.644: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Sep 3 19:47:35.644: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Sep 3 19:47:35.644: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: REGISTER sip:192.168.1.2 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.30:5060;branch=z9hG4bK-b297f361 From: "5011" ;tag=12887da2fe650436o0 To: "5011" Call-ID: 358f9193-fdb184d@192.168.1.30 CSeq: 45683 REGISTER Max-Forwards: 70 Authorization: Digest username="5011",realm="",nonce="8A84F2ED03BE3BB5",uri="sip:192.168.1.2",algorithm=MD5,response="95268dcd8c8fbedd4903608c2c4737ec",qop=auth,nc=00000001,cnonce="d319e0c7" Contact: "5011" ;expires=600 User-Agent: Cisco/SPA525G2-7.5.5a Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE Supported: replaces Sep 3 19:47:35.644: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Sep 3 19:47:35.644: //92087/916007C1B34B/SIP/Info/verbose/4096/sipSPIFindRegisterCcb: *****CCB found in UAS Request table. ccb=0x22B2AA98 Sep 3 19:47:35.644: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x3F01EE68) counter, current msg->refCount = 2 Sep 3 19:47:35.644: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 192.168.1.30,Port 5060, Transport 1, SentBy Port 5060vrfid 0 Sep 3 19:47:35.644: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT Sep 3 19:47:35.644: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 192.168.1.30,Port 5060, Transport 1, SentBy Port 5060vrfid 0 Sep 3 19:47:35.644: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x3F01EE68) counter, current msg->refCount = 3 Sep 3 19:47:35.644: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x3F01EE68) counter, current msg->refCount = 2 Sep 3 19:47:35.644: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x3F01EE68) counter, current msg->refCount = 3 Sep 3 19:47:35.644: //92087/916007C1B34B/SIP/Info/verbose/4096/sipSPIAssignCcbLastRequest: Current ccb(0x22B2AA98)->last_request = 0x3F01EE68, refCount = 3 Sep 3 19:47:35.644: //92087/916007C1B34B/SIP/Event/sact_idle_new_message_register: ccsip_api_register_ind return value : SIP_SUCCESS Sep 3 19:47:35.644: //92087/916007C1B34B/SIP/State/sipSPIChangeState: 0x22B2AA98 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE) Sep 3 19:47:35.644: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x3F01EE68) counter, current msg->refCount = 2 Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3A016664 Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/notify/262144/ccsip_register_process_incoming_register: CCSIP_REGISTER:: REGISTER request Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/notify/262144/ccsip_spi_register_incoming_registration: registration expires timer max is 3600 and min is 60 Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Error/ccsip_reg_search_call_id_table: No entry found in sipCallID Table Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Info/info/262144/ccsip_process_registration_passthrough: RCB Pointer : [0x0] Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/verbose/1024/sipSPIGetViaHostInURLFormat: VIA URL:sip:192.168.1.30:5060, Host:192.168.1.30 Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/info/2048/sipSPIGetRegisterConfig: Peer-Tag = 0, Reg-Pthru = Disable Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/verbose/10240/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0 Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/verbose/2048/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0 Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/notify/10240/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/critical/262144/ccsip_process_registration_passthrough: Register not for passthrough, Try CME Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/info/262144/ccsip_process_registration_passthrough: Resetting peer_tag Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/info/262144/ccsip_spi_register_incoming_registration: Register for CME case Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_spi_register_get_rcb: Getting New RCB [0x22D5F338] Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/verbose/262144/ccsip_spi_update_cc_callid: ccCallId for RCB is 92090 Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Error/sipSPI_validate_own_ip_addr: ReqLine IP addr does not match with host IP addr Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/info/65536/ccsip_sipline_set_vrf: Phone number 5011 from contact passed to this function Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Info/info/65536/ccsip_sipline_set_vrf: Obtained phone tag (0) from Dial-peer Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Info/info/65536/ccsip_sipline_set_vrf: Getting phone index for phone 5011 Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Info/verbose/512/ccsip_get_vrf_from_sip_bind: vrfid 0 for tag 0, sip_vrfid 0, voice_vrfid 0 Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: ip_best_local_address 192.168.1.2 for SIP Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 192.168.1.2 Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Error/ccsip_spi_register_incoming_registration: Registration Authorization failed with authorization header=Digest username="5011",realm="",nonce="8A84F2ED03BE3BB5",uri="sip:192.168.1.2",algorithm=MD5,response="95268dcd8c8fbedd4903608c2c4737ec",qop=auth,nc=00000001,cnonce="d319e0c7" Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/notify/262144/ccsip_spi_registration_failed: Sending Challenge 401/407 response Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/notify/262144/ccsip_spi_registration_failed: Sending Register Response 401 Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_REGISTER_RESP Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/verbose/262144/ccsipGetCCBFromRCB: Retrived CCB pointer [0x22B2AA98] Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Info/verbose/262144/sipSPIFreePthruDataFromRPCBorRCB: RCB =[0x22D5F338].. RPCB =[0x0] Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Info/verbose/9216/sipSPIPassThruHdrContainerFreeHelper: Data -->[0x0] Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Error/sipSPI_ipip_PassthruContentContainerFreeHelper: Null ContentQ - Exit Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Error/ccsip_rpcb_search_cc_call_id_table: No entry found in ccCallID Table Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_spi_register_free_rcb: Freeing rcb [0x22D5F338] Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 41 Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 13 event Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3A016664 with refCount = 1 Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/info/4096/sipSPISendResponse: Associated container=0x239FE1C0 to REGISTER Response 401 Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Transport/sipSPISendResponse: Sending INFO Response to the transport layer Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Transport/sipSPITransportSendMessage: msg=0x3A016664, addr=192.168.1.30, port=5060, sentBy_port=5060, local_addr=, is_req=0, transport=1, switch=0, callBack=0x35A1ABC0 Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x3A016664 to default port=5060 Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:192.168.1.30, rport:5060 with laddr: Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: gcb=0x22B2AA98 is already on connection=0x2247CC04 context_list Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x3A016664 Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x3A016664, addr=192.168.1.30, port=5060, local_addr=, connId=3 vrfid=0 for UDP Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x3F01EE68) counter, current msg->refCount = 1 Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/State/sipSPIChangeState: 0x22B2AA98 : State change from (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Sep 3 19:47:35.648: //92087/916007C1B34B/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.1.30:5060;branch=z9hG4bK-b297f361 From: "5011" ;tag=12887da2fe650436o0 To: "5011" ;tag=256E5510-369 Date: Sun, 03 Sep 2017 19:47:35 GMT Call-ID: 358f9193-fdb184d@192.168.1.30 Server: Cisco-SIPGateway/IOS-15.7.3.M CSeq: 45683 REGISTER WWW-Authenticate: Digest realm="",nonce="8A84F2ED03BE3BB5",algorithm=MD5,qop="auth" Content-Length: 0 Sep 3 19:47:35.648: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3A016664 Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Info/verbose/512/ccsip_get_vrf_from_sip_bind: vrfid 0 for tag 0, sip_vrfid 0, voice_vrfid 0 Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x22B3E0D0) with key=[177726] to table Sep 3 19:48:04.424: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init: Sep 3 19:48:04.424: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init: Sep 3 19:48:04.424: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised.. Sep 3 19:48:04.424: //-1/000000000000/SIP/Info/notify/262144/ccsipRegisterSetTargetInfo: p2p mode with Registrar Server = ipv4:192.168.1.2 Sep 3 19:48:04.424: //-1/000000000000/SIP/Info/verbose/262144/ccsipRegisterSetTargetInfo: Parsing The Registrar Address Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Info/verbose/5120/sipSPIGetOutboundHostAndDestHostPrivate: CCSIP: target_host : 192.168.1.2 target_port : 5060 Sep 3 19:48:04.424: //-1/000000000000/SIP/Info/verbose/5120/sipSPIValidateAndCopyOutboundHost: CCSIP: copy target_host to outbound_host Sep 3 19:48:04.424: //-1/000000000000/SIP/Info/critical/8192/sipSPIOutboundProxyReuse: Do not reuse Outbound Proxy IP adress and Port Sep 3 19:48:04.424: //-1/000000000000/SIP/Info/verbose/262144/ccsip_spi_outgoing_register: ccb's vrfid is set to 0 Sep 3 19:48:04.424: //-1/000000000000/SIP/State/sipSPIChangeState: 0x22B3E0D0 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Sep 3 19:48:04.424: //-1/000000000000/SIP/Info/verbose/6144/ccsip_spi_registrar_add_expires_header: Inside ccsip_spi_registrar_add_expires_header for Expires Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_OUTBOUND_REGISTER Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Info/info/262144/sipSPIIncrementOverloadCount: Local 1 Global 1 Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 40 Sep 3 19:48:04.424: //-1/000000000000/SIP/Info/verbose/262144/act_idle_outgoing_register: In act_idle_outgoing_register Sep 3 19:48:04.424: //92091/000000000000/SIP/Info/info/262144/act_idle_outgoing_register: Send REGISTER to 192.168.1.2:5060 Sep 3 19:48:04.424: //92091/000000000000/SIP/Info/verbose/4096/sipSPIUaddCcbToUACTable: ****Adding to UAC table.0x22B3E0D0 590DC5E0-8A7811E7-8ADECBC6-A9D31E24 Sep 3 19:48:04.424: //92091/000000000000/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x22B3E0D0 key=590DC5E0-8A7811E7-8ADECBC6-A9D31E24 balance 1 Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Info/verbose/512/ccsip_get_vrf_from_sip_bind: vrfid 0 for tag 0, sip_vrfid 0, voice_vrfid 0 Sep 3 19:48:04.424: //92091/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 3 19:48:04.424: //92091/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: ip_best_local_address 192.168.1.2 for SIP Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 192.168.1.2 Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3FB743AC with refCount = 1 Sep 3 19:48:04.424: //92091/000000000000/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 8 event Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT Sep 3 19:48:04.424: Parse Error: url_parseSipUrl: Received Bad Port Sep 3 19:48:04.424: //92091/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:48:04.424: //92091/000000000000/SIP/Info/info/4096/sipSPISendRegister: Associated container=0x23A00790 to Register Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Sep 3 19:48:04.424: //92091/000000000000/SIP/Transport/sipSPISendRegister: Sending REGISTER to the transport layer Sep 3 19:48:04.424: //92091/000000000000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE Sep 3 19:48:04.424: //92091/000000000000/SIP/Transport/sipSPITransportSendMessage: msg=0x3FB743AC, addr=192.168.1.2, port=5060, sentBy_port=0, local_addr=, is_req=1, transport=1, switch=0, callBack=0x35A1AC88 Sep 3 19:48:04.424: //92091/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:48:04.424: //92091/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:48:04.424: //92091/000000000000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:192.168.1.2, rport:5060 with laddr: Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x22B3E0D0 with connection=0x2247C3E4 context list Sep 3 19:48:04.424: //92091/000000000000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x3FB743AC Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x3FB743AC, addr=192.168.1.2, port=5060, local_addr=, connId=2 vrfid=0 for UDP Sep 3 19:48:04.424: //92091/000000000000/SIP/State/sipSPIChangeState: 0x22B3E0D0 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) Sep 3 19:48:04.424: //92091/000000000000/SIP/State/sipSPIChangeState: 0x22B3E0D0 : State change from (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) Sep 3 19:48:04.424: //92091/000000000000/SIP/Msg/ccsipDisplayMsg: Sent: REGISTER sip:192.168.1.2:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bKC892FD3 From: ;tag=256EC5C4-B08 To: Date: Sun, 03 Sep 2017 19:48:04 GMT Call-ID: 590DC5E0-8A7811E7-8ADECBC6-A9D31E24 User-Agent: Cisco-SIPGateway/IOS-15.7.3.M Max-Forwards: 70 Timestamp: 1504468084 CSeq: 3110 REGISTER Contact: Expires: 3600 Supported: path Content-Length: 0 Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3FB743AC Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3FB743AC with refCount = 1 Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3EFF668C with refCount = 1 Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.1.2]:59870, local_address:[ - ] Sep 3 19:48:04.424: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3FB743AC Sep 3 19:48:04.428: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Sep 3 19:48:04.428: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Sep 3 19:48:04.428: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: REGISTER sip:192.168.1.2:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bKC892FD3 From: ;tag=256EC5C4-B08 To: Date: Sun, 03 Sep 2017 19:48:04 GMT Call-ID: 590DC5E0-8A7811E7-8ADECBC6-A9D31E24 User-Agent: Cisco-SIPGateway/IOS-15.7.3.M Max-Forwards: 70 Timestamp: 1504468084 CSeq: 3110 REGISTER Contact: Expires: 3600 Supported: path Content-Length: 0 Sep 3 19:48:04.428: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Sep 3 19:48:04.428: Parse Error: url_parseSipUrl: Received Bad Port Sep 3 19:48:04.428: //92091/000000000000/SIP/Error/sippmh_cmp_tags: Parse Error in request header Sep 3 19:48:04.428: //92091/000000000000/SIP/Info/info/4096/sipSPICheckFromToRequest: Trying with child CCB 0x0 index 0 curr_child 0 Sep 3 19:48:04.428: //92091/000000000000/SIP/Error/sipSPICheckFromToRequest: Failed FROM/TO Request check - IGNORE IF HAIRPIN CALL old_from: ;tag=256EC5C4-B08 old_to: new_from: ;tag=256EC5C4-B08 new_to: Sep 3 19:48:04.428: Parse Error: url_parseSipUrl: Received Bad Port Sep 3 19:48:04.428: Parse Error: url_parseSipUrl: Received Bad Port Sep 3 19:48:04.428: Parse Error: url_parseSipUrl: Received Bad Port Sep 3 19:48:04.428: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x22AAFDE0) with key=[177727] to table Sep 3 19:48:04.428: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init: Sep 3 19:48:04.428: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init: Sep 3 19:48:04.428: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised.. Sep 3 19:48:04.428: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 192.168.1.2,Port 5060, Transport 1, SentBy Port 5060vrfid 0 Sep 3 19:48:04.428: //-1/xxxxxxxxxxxx/SIP/Info/verbose/512/ccsip_get_vrf_from_sip_bind: vrfid 0 for tag 0, sip_vrfid 0, voice_vrfid 0 Sep 3 19:48:04.428: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 3 19:48:04.428: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: VRF id = 0 Sep 3 19:48:04.428: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: ip_best_local_address 192.168.1.2 for SIP Sep 3 19:48:04.428: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 192.168.1.2 Sep 3 19:48:04.428: //-1/A2931BA7B34C/SIP/State/sipSPIChangeState: 0x22AAFDE0 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Sep 3 19:48:04.428: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 192.168.1.2,Port 59870, Transport 1, SentBy Port 5060vrfid 0 Sep 3 19:48:04.428: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT Sep 3 19:48:04.428: Parse Error: url_parseSipUrl: Received Bad Port Sep 3 19:48:04.428: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 192.168.1.2,Port 59870, Transport 1, SentBy Port 5060vrfid 0 Sep 3 19:48:04.428: Parse Error: url_parseSipUrl: Received Bad Port Sep 3 19:48:04.428: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x3EFF668C) counter, current msg->refCount = 2 Sep 3 19:48:04.428: //-1/A2931BA7B34C/SIP/Info/verbose/4096/sipSPIAssignCcbLastRequest: Current ccb(0x22AAFDE0)->last_request = 0x3EFF668C, refCount = 2 Sep 3 19:48:04.428: Parse Error: url_parseSipUrl: Received Bad Port Sep 3 19:48:04.428: Parse Error: url_parseSipUrl: Received Bad Port Sep 3 19:48:04.428: Parse Error: url_parseSipUrl: Received Bad Port Sep 3 19:48:04.428: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3FB743AC with refCount = 1 Sep 3 19:48:04.428: Parse Error: url_parseSipUrl: Received Bad Port Sep 3 19:48:04.428: //-1/A2931BA7B34C/SIP/Transport/sipSPISendResponse: Sending INFO Response to the transport layer Sep 3 19:48:04.428: //-1/A2931BA7B34C/SIP/Transport/sipSPITransportSendMessage: msg=0x3FB743AC, addr=192.168.1.2, port=59870, sentBy_port=5060, local_addr=, is_req=0, transport=1, switch=0, callBack=0x35A1ABC0 Sep 3 19:48:04.428: //-1/A2931BA7B34C/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:48:04.428: //-1/A2931BA7B34C/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:48:04.428: //-1/A2931BA7B34C/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Sep 3 19:48:04.428: //-1/A2931BA7B34C/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x3FB743AC to default port=5060 Sep 3 19:48:04.428: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:192.168.1.2, rport:5060 with laddr: Sep 3 19:48:04.428: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x22AAFDE0 with connection=0x2247C3E4 context list Sep 3 19:48:04.428: //-1/A2931BA7B34C/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x3FB743AC Sep 3 19:48:04.428: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x3FB743AC, addr=192.168.1.2, port=5060, local_addr=, connId=2 vrfid=0 for UDP Sep 3 19:48:04.428: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x3EFF668C) counter, current msg->refCount = 1 Sep 3 19:48:04.428: //-1/A2931BA7B34C/SIP/State/sipSPIChangeState: 0x22AAFDE0 : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Sep 3 19:48:04.428: //-1/A2931BA7B34C/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 400 Bad Request - 'Malformed/Missing FROM: field' Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bKC892FD3 From: ;tag=256EC5C4-B08 To: Date: Sun, 03 Sep 2017 19:48:04 GMT Call-ID: 590DC5E0-8A7811E7-8ADECBC6-A9D31E24 Server: Cisco-SIPGateway/IOS-15.7.3.M Timestamp: 1504468084 CSeq: 3110 REGISTER Content-Length: 0 Sep 3 19:48:04.428: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3FB743AC Sep 3 19:48:04.428: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3FB743AC with refCount = 1 Sep 3 19:48:04.432: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x23BE2E58 with refCount = 1 Sep 3 19:48:04.432: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.1.2]:59870, local_address:[ - ] Sep 3 19:48:04.432: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3FB743AC Sep 3 19:48:04.432: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Sep 3 19:48:04.432: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Sep 3 19:48:04.432: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Sep 3 19:48:04.432: Parse Error: url_parseSipUrl: Received Bad Port Sep 3 19:48:04.432: //92091/000000000000/SIP/Error/sipSPIMatchRespToReqTran: Error in matching From header tags Sep 3 19:48:04.432: Parse Error: url_parseSipUrl: Received Bad Port Sep 3 19:48:04.432: Parse Error: url_parseSipUrl: Received Bad Port Sep 3 19:48:04.432: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 400 Bad Request - 'Malformed/Missing FROM: field' Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bKC892FD3 From: ;tag=256EC5C4-B08 To: Date: Sun, 03 Sep 2017 19:48:04 GMT Call-ID: 590DC5E0-8A7811E7-8ADECBC6-A9D31E24 Server: Cisco-SIPGateway/IOS-15.7.3.M Timestamp: 1504468084 CSeq: 3110 REGISTER Content-Length: 0 Sep 3 19:48:04.432: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/sipSPILocateInviteDialogCCB: Could not find matching transaction for this response, Dropping it Sep 3 19:48:04.432: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x23BE2E58 Sep 3 19:48:04.924: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3FB743AC with refCount = 1 Sep 3 19:48:04.924: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT Sep 3 19:48:04.924: Parse Error: url_parseSipUrl: Received Bad Port Sep 3 19:48:04.924: //92091/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:48:04.924: //92091/000000000000/SIP/Info/info/4096/sipSPISendRegister: Associated container=0x23A00790 to Register Sep 3 19:48:04.924: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0 Sep 3 19:48:04.924: //92091/000000000000/SIP/Transport/sipSPISendRegister: Sending REGISTER to the transport layer Sep 3 19:48:04.924: //92091/000000000000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE Sep 3 19:48:04.924: //92091/000000000000/SIP/Transport/sipSPITransportSendMessage: msg=0x3FB743AC, addr=192.168.1.2, port=5060, sentBy_port=0, local_addr=, is_req=1, transport=1, switch=0, callBack=0x0 Sep 3 19:48:04.924: //92091/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:48:04.924: //92091/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1 Sep 3 19:48:04.924: //92091/000000000000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Sep 3 19:48:04.924: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:192.168.1.2, rport:5060 with laddr: Sep 3 19:48:04.924: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: gcb=0x22B3E0D0 is already on connection=0x2247C3E4 context_list Sep 3 19:48:04.924: //92091/000000000000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x3FB743AC Sep 3 19:48:04.924: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x3FB743AC, addr=192.168.1.2, port=5060, local_addr=, connId=2 vrfid=0 for UDP Sep 3 19:48:04.924: //92091/000000000000/SIP/Msg/ccsipDisplayMsg: Sent: REGISTER sip:192.168.1.2:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bKC892FD3 From: ;tag=256EC5C4-B08 To: Date: Sun, 03 Sep 2017 19:48:04 GMT Call-ID: 590DC5E0-8A7811E7-8ADECBC6-A9D31E24 User-Agent: Cisco-SIPGateway/IOS-15.7.3.M Max-Forwards: 70 Timestamp: 1504468084 CSeq: 3110 REGISTER Contact: Expires: 3600 Supported: path Content-Length: 0 Sep 3 19:48:04.924: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3FB743AC Sep 3 19:48:04.924: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3FB743AC with refCount = 1 Sep 3 19:48:04.924: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x23C3FF80 with refCount = 1 Sep 3 19:48:04.924: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.1.2]:59870, local_address:[ - ] Sep 3 19:48:04.924: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3FB743AC Sep 3 19:48:04.924: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Sep 3 19:48:04.924: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Sep 3 19:48:04.924: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: REGISTER sip:192.168.1.2:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bKC892FD3 From: ;tag=256EC5C4-B08 To: Date: Sun, 03 Sep 2017 19:48:04 GMT Call-ID: 590DC5E0-8A7811E7-8ADECBC6-A9D31E24 User-Agent: Cisco-SIPGateway/IOS-15.7.3.M Max-Forwards: 70 Timestamp: 1504468084 CSeq: 3110 REGISTER Contact: Expires: 3600 Supported: path Content-Length: 0 Sep 3 19:48:04.924: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog Sep 3 19:48:04.924: Parse Error: url_parseSipUrl: Received