SIP Phones Not registering in CUCME

HARIS_HUSSAIN · ‎09-07-2017

We have CUCM and SIP Srst for remote sites. For One of the site site the SRST is not working.

It is same configuration on all sites

voice-card 0
voice rtp send-recv
voice service voip
ip address trusted list
ipv4 0.0.0.0 0.0.0.0
allow-connections h323 to h323
allow-connections h323 to sip
allow-connections sip to h323
allow-connections sip to sip
no supplementary-service sip handle-replaces
fax protocol t38 version 0 ls-redundancy 0 hs-redundancy 0 fallback none
sip
bind control source-interface GigabitEthernet0/0
bind media source-interface GigabitEthernet0/0
registrar server expires max 600 min 60
no silent-discard untrusted
voice class codec 1
codec preference 1 g711ulaw
codec preference 2 g711alaw
codec preference 3 g729r8
codec preference 4 g729br8
voice class h323 1
h225 timeout tcp establish 3
h225 timeout setup 3
voice class custom-cptone UAE-TONES
dualtone disconnect
frequency 400
cadence 400 350 225 525
voice register global
mode esrst
timeouts interdigit 2
system message Failover SRST Mode
max-dn 10
max-pool 10
voice register pool 1
id network 172.21.88.0 mask 255.255.255.0
no digit collect kpml
voice-class codec 1

I have done a detailed debug below is what i found. It syas some error with reqLine IPaddress Validation.

Received:
REGISTER sip:172.21.88.2 SIP/2.0
Via: SIP/2.0/UDP 172.21.88.54:5060;branch=z9hG4bK7edeaa49
From: <sip:2457@172.21.88.2>;tag=009e1edec7c50a4162004d96-61f21fcc
To: <sip:2457@172.21.88.2>
Call-ID: 009e1ede-c7c5009c-4fe96048-570a93cd@172.21.88.54
Max-Forwards: 70
Date: Thu, 07 Sep 2017 08:09:20 GMT
CSeq: 2245 REGISTER
User-Agent: Cisco-CP7841/10.3.1
Contact: <sip:21d17c3c-1012-927b-2363-d786d37e5642@172.21.88.54:5060;transport=udp>;+sip.instance="<urn:uuid:00000000-0000-0000-0000-009e1edec7c5>";+u.sip!devicename.ccm.cisco.com="SEP009E1EDEC7C5";+u.sip!model.ccm.cisco.com="622"
Supported: extended-refer,norefersub,X-cisco-srtp-fallback,X-cisco-config,X-cisco-sis-7.0.0,X-cisco-xsi-8.5.1
Content-Length: 0
Reason: SIP;cause=200;text="cisco-alarm:10 Name=SEP009E1EDEC7C5 ActiveLoad=sip78xx.10-3-1-12.loads InactiveLoad=sip78xx.11-0-1-11.loads Last=tcp_timeout"
Expires: 3600

*Sep 7 08:09:55.650: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog
*Sep 7 08:09:55.650: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIFindRegisterCcb: *****CCB NOT found in UAS Request table. ccb=0x0
*Sep 7 08:09:55.650: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x3DD76E10) with key=[258] to table
*Sep 7 08:09:55.650: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init:
*Sep 7 08:09:55.650: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init:
*Sep 7 08:09:55.650: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised..
*Sep 7 08:09:55.650: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 172.21.88.54,Port 5060, Transport 1, SentBy Port 5060
*Sep 7 08:09:55.650: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 172.21.88.2 for SIP
*Sep 7 08:09:55.650: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 172.21.88.2 for SIP
*Sep 7 08:09:55.650: //-1/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 172.21.88.2
*Sep 7 08:09:55.650: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 172.21.88.2
*Sep 7 08:09:55.650: //-1/C491C5178CFF/SIP/State/sipSPIChangeState: 0x3DD76E10 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
*Sep 7 08:09:55.650: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.21.88.54,Port 5060, Transport 1, SentBy Port 5060
*Sep 7 08:09:55.650: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
*Sep 7 08:09:55.650: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 172.21.88.54,Port 5060, Transport 1, SentBy Port 5060
*Sep 7 08:09:55.650: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x3E69ABB8) counter, current msg->refCount = 2
*Sep 7 08:09:55.650: //-1/C491C5178CFF/SIP/Info/verbose/4096/sipSPIAssignCcbLastRequest: Current ccb(0x3DD76E10)->last_request = 0x3E69ABB8, refCount = 2
*Sep 7 08:09:55.650: //-1/C491C5178CFF/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x3DD76E10 key=009e1ede-c7c5009c-4fe96048-570a93cd@172.21.88.542457009e1edec7c50a4162004d96-61f21fcc balance 0
*Sep 7 08:09:55.650: //1660/C491C5178CFF/SIP/Event/sact_idle_new_message_register:
ccsip_api_register_ind return value : SIP_SUCCESS

*Sep 7 08:09:55.650: //1660/C491C5178CFF/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable: Adding call id 67C to table
*Sep 7 08:09:55.650: //1660/C491C5178CFF/SIP/State/sipSPIChangeState: 0x3DD76E10 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE)
*Sep 7 08:09:55.650: //1660/C491C5178CFF/SIP/Info/notify/262144/ccsip_register_process_incoming_register: CCSIP_REGISTER:: REGISTER request
*Sep 7 08:09:55.650: //1660/C491C5178CFF/SIP/Info/notify/262144/ccsip_spi_register_incoming_registration: registration expires timer max is 600 and min is 60

*Sep 7 08:09:55.650: //-1/xxxxxxxxxxxx/SIP/Error/ccsip_reg_search_call_id_table:
No entry found in sipCallID Table
*Sep 7 08:09:55.650: //-1/xxxxxxxxxxxx/SIP/Info/info/262144/ccsip_process_registration_passthrough: RCB Pointer : [0x0]
*Sep 7 08:09:55.650: //1660/C491C5178CFF/SIP/Info/verbose/1024/sipSPIGetViaHostInURLFormat: VIA URL:sip:172.21.88.54:5060, Host:172.21.88.54
*Sep 7 08:09:55.650: //1660/C491C5178CFF/SIP/Info/notify/10240/sipSPIGetRegisterConfig: Using Global Config
*Sep 7 08:09:55.650: //1660/C491C5178CFF/SIP/Info/info/2048/sipSPIGetRegisterConfig: Peer-Tag = 1, Reg-Pthru = Disable
*Sep 7 08:09:55.650: //1660/C491C5178CFF/SIP/Info/verbose/10240/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0
*Sep 7 08:09:55.650: //1660/C491C5178CFF/SIP/Info/verbose/2048/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0
*Sep 7 08:09:55.650: //1660/C491C5178CFF/SIP/Info/notify/10240/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled
*Sep 7 08:09:55.650: //1660/C491C5178CFF/SIP/Info/critical/262144/ccsip_process_registration_passthrough: Register not for passthrough, Try CME
*Sep 7 08:09:55.650: //1660/C491C5178CFF/SIP/Info/info/262144/ccsip_spi_register_incoming_registration: Register for CME case
*Sep 7 08:09:55.650: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_spi_register_get_rcb: Getting New RCB [0x2103ECA0]
*Sep 7 08:09:55.654: //1660/C491C5178CFF/SIP/Info/verbose/262144/ccsip_spi_update_cc_callid: ccCallId for RCB is 1661
*Sep 7 08:09:55.654: //-1/xxxxxxxxxxxx/SIP/Error/sipSPI_validate_own_ip_addr:
ReqLine IP addr does not match with host IP addr
*Sep 7 08:09:55.654: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x3DD92A84) with key=[259] to table
*Sep 7 08:09:55.654: //0/000000000000/SIP/Info/info/4096/ccsip_new_scb: Created new scb: 0x3DD92A84 with id: -1 peer tag 0
*Sep 7 08:09:55.654: //-1/xxxxxxxxxxxx/SIP/Event/ccsip_spi_refer_client: Queued event from SIP SPI : SIPSPI_EV_CC_REFER
*Sep 7 08:09:55.658: //1660/C491C5178CFF/SIP/Error/ccsip_spi_register_incoming_registration:
Error during REGISTER for contact - 172.21.88.54 2457
*Sep 7 08:09:55.658: //1660/C491C5178CFF/SIP/Info/notify/262144/ccsip_spi_registration_failed: Sending Register Response 500

*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_REGISTER_RESP
*Sep 7 08:09:55.658: //1660/C491C5178CFF/SIP/Info/verbose/262144/ccsipGetCCBFromRCB: Retrived CCB pointer [0x3DD76E10]
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/verbose/262144/sipSPIFreePthruDataFromRPCBorRCB: RCB =[0x2103ECA0].. RPCB =[0x0]
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/verbose/9216/sipSPIPassThruHdrContainerFreeHelper: Data -->[0x0]
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Error/sipSPI_ipip_PassthruContentContainerFreeHelper:
Null ContentQ - Exit
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Error/ccsip_rpcb_search_cc_call_id_table:
No entry found in ccCallID Table
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_spi_register_free_rcb: Freeing rcb [0x2103ECA0]
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 7 for event 209
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_spi_process_app_subscribe_event: Event [SIPSPI_EV_CC_REFER] received in State [SUBSCRIBE_STATE_IDLE]
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_tcb: Created TCB: 0x22C8381C
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/act_idle_refer_event: TCB 0x22C8381C's parent is 0x3DD92A84
*Sep 7 08:09:55.658: //0/000000000000/SIP/Info/info/16384/act_idle_refer_event: Initiating Out-Of-Call-Context Refer
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateTCBFromTargetInfo: Dialog Transaction Address 172.21.88.54,Port 5060, Port Present TRUE, Transport 1, FQDN 955899312
*Sep 7 08:09:55.658: //0/000000000000/SIP/Info/info/10240/resolve_sig_ip_address_to_bind: OOD-SCB, check the bind config on SCB
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/ccsip_get_ifaddress: ip_address IPv4 172.21.88.2 for SIP
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_ip_address_to_bind: ip_get_ifaddress IPv4 172.21.88.2 for SIP
*Sep 7 08:09:55.658: //0/000000000000/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: signaling bind address : 172.21.88.2
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 172.21.88.2
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/sipSPICreateSubscribeKey: Generated Subscribe Key : C492FD66-92DA11E7-8D00D14C-A397EFB4@172.21.88.227811158-21E5
*Sep 7 08:09:55.658: //0/000000000000/SIP/Info/verbose/4096/sipSPIPutSCBInClientTable: Inserting SCB with key C492FD66-92DA11E7-8D00D14C-A397EFB4@172.21.88.227811158-21E5 into ClientTable
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x2321DBC0 with refCount = 1
*Sep 7 08:09:55.658: //0/000000000000/SIP/Info/info/262144/sipSPIGenerateReferredByValue: No registrar cfg. Using default value for refby host : 172.21.88.2
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 292
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/act_idle_continue_refer_event: TCB 0x22C8381C's method is 110
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/sipSPIUpdateTCBPackage: Current tcb(0x22C8381C)->package = 0x2321DBC0, refCount = 1
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIUpdateTCBClientMarker: Client TCB's Marker Updated to: z9hG4bK5F1380
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_edb: Created new edb(0x22C88788)
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIUpdateEDBEvent: EDB updated with Event Name: refer Event ID:
*Sep 7 08:09:55.658: //0/000000000000/SIP/Info/info/4096/sipSPICreateNewEDB: Q'd EDB(0x22C88788) on SCB(0x3DD92A84)
*Sep 7 08:09:55.658: //0/000000000000/SIP/Info/verbose/4096/sipSPICreateNewEDB: There are 1 EDB's on edbQ
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/sipSPIQueueTcbOnReferEdb: Q'd TCB(0x22C8381C) on EDB(0x22C88788)
*Sep 7 08:09:55.658: //0/000000000000/SIP/Info/verbose/4096/sipSPIQueueTcbOnReferEdb: There are 1 TCB's on tcbQ
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPITCBSendPackage: Sending Package on tcb: 0x22C8381C and parent: 0x3DD92A84

*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x2321DBC0) counter, current msg->refCount = 2
*Sep 7 08:09:55.658: //0/000000000000/SIP/Transport/sipSPITransportSendMessage: msg=0x2321DBC0, addr=172.21.88.54, port=5060, sentBy_port=0, local_addr=172.21.88.2, is_req=1, transport=1, switch=0, callBack=0x3520B5F4
*Sep 7 08:09:55.658: //0/000000000000/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1
*Sep 7 08:09:55.658: //0/000000000000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:172.21.88.54, rport:5060 with laddr:172.21.88.2

*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x3DD92A84 with connection=0x21F73A5C context list
*Sep 7 08:09:55.658: //0/000000000000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x2321DBC0
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x2321DBC0, addr=172.21.88.54, port=5060, local_addr=172.21.88.2, connId=4 for UDP
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/sipSPIKickoffTcbReTxTimer: Kicking off ReTx Timer for Client TCB (0x22C8381C) with 10 retries and 500 milliseconds initial retx
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_new_timer_context: Created timer context(0x3E607C6C)
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/act_idle_continue_refer_event: Changing from State: SUBSCRIBE_STATE_IDLE to state SUBSCRIBE_STATE_DIALOG_PENDING
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 41
*Sep 7 08:09:55.658: //1660/C491C5178CFF/SIP/Info/verbose/8192/sipSPIPresendProcessing: Presend Processing called for 13 event
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x218D7E9C with refCount = 1
*Sep 7 08:09:55.658: //1660/C491C5178CFF/SIP/Info/info/4096/sipSPISendResponse: Associated container=0x3E60700C to REGISTER Response 500
*Sep 7 08:09:55.658: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 0
*Sep 7 08:09:55.658: //1660/C491C5178CFF/SIP/Transport/sipSPISendResponse: Sending INFO Response to the transport layer
*Sep 7 08:09:55.658: //1660/C491C5178CFF/SIP/Transport/sipSPITransportSendMessage: msg=0x218D7E9C, addr=172.21.88.54, port=5060, sentBy_port=5060, local_addr=172.21.88.2, is_req=0, transport=1, switch=0, callBack=0x351800F0
*Sep 7 08:09:55.658: //1660/C491C5178CFF/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1
*Sep 7 08:09:55.662: //1660/C491C5178CFF/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Sep 7 08:09:55.662: //1660/C491C5178CFF/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x218D7E9C to default port=5060
*Sep 7 08:09:55.662: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:172.21.88.54, rport:5060 with laddr:172.21.88.2

*Sep 7 08:09:55.662: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x3DD76E10 with connection=0x21F73A5C context list
*Sep 7 08:09:55.662: //1660/C491C5178CFF/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x218D7E9C
*Sep 7 08:09:55.662: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x218D7E9C, addr=172.21.88.54, port=5060, local_addr=172.21.88.2, connId=4 for UDP
*Sep 7 08:09:55.662: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x3E69ABB8) counter, current msg->refCount = 1
*Sep 7 08:09:55.662: //1660/C491C5178CFF/SIP/State/sipSPIChangeState: 0x3DD76E10 : State change from (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
*Sep 7 08:09:55.666: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
REFER sip:2457@172.21.88.54:5060 SIP/2.0
Via: SIP/2.0/UDP 172.21.88.2:5060;branch=z9hG4bK5F1380
From: <sip:172.21.88.2>;tag=27811158-21E5
To: <sip:2457@172.21.88.54>
Call-ID: C492FD66-92DA11E7-8D00D14C-A397EFB4@172.21.88.2
CSeq: 101 REFER
Max-Forwards: 70
Contact: <sip:172.21.88.2:5060>
User-Agent: Cisco-SIPGateway/IOS-15.3.3.M6
Timestamp: 1504771795
Require: norefersub
Refer-To: cid:066277000
Content-ID: <066277000>
Content-Type: application/x-cisco-remotecc-request+xml
Referred-By: <sip:172.21.88.2>
Content-Length: 292

<?xml version="1.0" encoding="UTF-8"?><x-cisco-remotecc-request><statuslineupdatereq><action>notify_display</action><statustext>Max Phones Exceeded</statustext><displaytimeout>10</displaytimeout><linenumber>0</linenumber><priority>1</priority></statuslineupdatereq></x-cisco-remotecc-request>
*Sep 7 08:09:55.666: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x2321DBC0) counter, current msg->refCount = 1
*Sep 7 08:09:55.666: //1660/C491C5178CFF/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 500 Internal Server Error
Via: SIP/2.0/UDP 172.21.88.54:5060;branch=z9hG4bK7edeaa49
From: <sip:2457@172.21.88.2>;tag=009e1edec7c50a4162004d96-61f21fcc
To: <sip:2457@172.21.88.2>;tag=27811150-2204
Date: Thu, 07 Sep 2017 08:09:55 GMT
Call-ID: 009e1ede-c7c5009c-4fe96048-570a93cd@172.21.88.54
Server: Cisco-SIPGateway/IOS-15.3.3.M6
CSeq: 2245 REGISTER
Content-Length: 0

*Sep 7 08:09:55.666: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x218D7E9C
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x218D7E9C with refCount = 1
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3CD2B41C with refCount = 1
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [172.21.88.54]:5060, local_address:[172.21.88.2]
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x218D7E9C
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Error/ccsip_get_method_from_request:
Unable to extract request line from message
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Subscribe Dialog
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/sipSPICreateSubscribeKey: Generated Subscribe Key : C492FD66-92DA11E7-8D00D14C-A397EFB4@172.21.88.227811158-21E5
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetSCBFromClientTable: Searching for SCB in client table with key C492FD66-92DA11E7-8D00D14C-A397EFB4@172.21.88.227811158-21E5
*Sep 7 08:09:55.726: //0/000000000000/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.21.88.2:5060;branch=z9hG4bK5F1380
From: <sip:172.21.88.2>;tag=27811158-21E5
To: <sip:2457@172.21.88.54>;tag=009e1edec7c50a424fb2972a-36487cff
Call-ID: C492FD66-92DA11E7-8D00D14C-A397EFB4@172.21.88.2
Date: Thu, 07 Sep 2017 08:09:20 GMT
CSeq: 101 REFER
Server: Cisco-CP7841/10.3.1
Contact: <sip:21d17c3c-1012-927b-2363-d786d37e5642@172.21.88.54:5060;transport=udp>
Content-Length: 0

*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetAnalogousSubscribeEvent: Event entering: 1
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_spi_process_event: Event [SIPSPI_EV_NEW_MSG] received in State [SUBSCRIBE_STATE_DIALOG_PENDING]
*Sep 7 08:09:55.726: //0/000000000000/SIP/Info/verbose/4096/sipSPIFindTCBonSCB: Found TCB(0x22C8381C) on SCB(0x3DD92A84)
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/sipSPIClientDialogPendingNewResponse: Changing from State: SUBSCRIBE_STATE_DIALOG_PENDING to state SUBSCRIBE_STATE_ACTIVE
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x2321DBC0
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIFreeOneTCB: Sizeof tcbQ: 1
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIFreeOneTCB: DeQ'd TCB(0x22C8381C) from EDB(0x22C88788)
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIFreeOneTCB: EnQing TCB(0x22C8381C) for reuse
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x3CD2B41C) counter, current msg->refCount = 2
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Event/ccsip_api_initiate_subscription_termination: Queued event from SIP SPI : SIPSPI_EV_SUBSCRIPTION_TERMINATED
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x3CD2B41C) counter, current msg->refCount = 1
*Sep 7 08:09:55.726: //0/000000000000/SIP/Info/info/4096/sipSPIReportRequestSendStatus: ccsip_api_refer_result returned: SIP_SUCCESS
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3CD2B41C
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 7 for event 210
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_spi_process_app_subscribe_event: Event [SIPSPI_EV_SUBSCRIPTION_TERMINATED] received in State [SUBSCRIBE_STATE_ACTIVE]
*Sep 7 08:09:55.726: //0/000000000000/SIP/Info/verbose/4096/act_subscription_terminated: Resetting Client EDB flag
*Sep 7 08:09:55.726: //0/000000000000/SIP/Info/verbose/4096/sipSPIFreeOneEDB: There are 1 EDBs on edbQ
*Sep 7 08:09:55.726: //0/000000000000/SIP/Info/verbose/4096/sipSPIFreeOneEDB: DeQ'd EDB(0x22C88788)
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIFreeOneEDB: EnQing EDB(0x22C88788) for reuse
*Sep 7 08:09:55.726: //0/000000000000/SIP/Info/verbose/4096/sipSPITerminateEvent: Freeing SCB(0x3DD92A84), 0 active events present
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[259] removed.
*Sep 7 08:09:55.726: //0/000000000000/SIP/Info/verbose/4096/sipSPIRemoveSCBFromClientTable: Removing SCB(0x3DD92A84) with Key(C492FD66-92DA11E7-8D00D14C-A397EFB4@172.21.88.227811158-21E5) from Client Table
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x21F71C9C, addr=172.21.88.54, port=5060, local_addr=172.21.88.2, unregistering context=0x3DD92A84
*Sep 7 08:09:55.726: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstancePurgeContextInConnection: Purging context gcb=0x3DD92A84 from the connection=0x21F73A5C context list
*Sep 7 08:09:55.726: //0/000000000000/SIP/Info/verbose/4096/sipSPIFreeOneSCB: EnQing SCB(0x3DD92A84) for reuse
*Sep 7 08:09:55.958: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x3CD13AF0 with refCount = 1
*Sep 7 08:09:55.958: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x218D7E9C with refCount = 1
*Sep 7 08:09:55.958: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [172.21.88.55]:5060, local_address:[172.21.88.2]
*Sep 7 08:09:55.958: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x3CD13AF0
*Sep 7 08:09:55.958: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
*Sep 7 08:09:55.958: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0
*Sep 7 08:09:55.958: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Chris Deren · ‎09-07-2017

can you try adding no silent-discard untrusted under the global SIP configuration?