SIP Phone not registering - strange case

Antonio Brandao · ‎03-01-2013

Hi All,

I have a SIP phone with problem to register on CM.

I had follow the steps

1) Created an user

2) Created an device

3) Created a DN

4) Did setup SIP phone with CM figures

And linked all them and when noticed it´s having some issue with user/password. The case is, I had verified all field I could both in CM and SIP phone but still getting this message.

Any comments ? Trace output below

Regards

AB

|1,100,213,1.1017^172.16.1.12^*

09:34:35.116 |//SIP/Stack/Info/0xb4550f50/****Adding to UAS Request table.|1,100,213,1.1017^172.16.1.12^*

09:34:35.116 |//SIP/Stack/Info/0xb4550f50/Added to table. ccb=0xb4550f50 key=7joPS0-dX*B33h1@172.16.1.2021015RzJ3h1-a47OG|1,100,213,1.1017^172.16.1.12^*

09:34:35.116 |//SIP/SIPHandler/ccbId=0/scbId=0/findTrunkInfoByAddr: Cannot find the SIP Trunk with Name=172.16.1.12, Source Port=5060, IpAddress Type=0|1,100,213,1.1017^172.16.1.12^*

09:34:35.116 |//SIP/SIPHandler/ccbId=979/scbId=0/findDevicePID: Routed to SIPStationInit|1,100,213,1.1017^172.16.1.12^*

09:34:35.116 |SIPStationInit: Parsed +u.sip!devicename.ccm: SEP001A3F03E0D1|1,100,213,1.1017^172.16.1.12^*

09:34:35.116 |SIPStationInit: connId=0, SEP001A3F03E0D1, 1015@172.16.1.12:5060, New [dynamic] device registering over UDP transport|1,100,213,1.1017^172.16.1.12^*

09:34:35.116 |SIPStationInit: connID=0, SEP001A3F03E0D1, 172.16.1.12:5060, New targetEntry created|1,100,213,1.1017^172.16.1.12^*

09:34:35.116 |SIPStationInit: connID=0, SEP001A3F03E0D1, 172.16.1.12:5060, (RegTrace 0xb43da5d8) Enqueuing register for ccbID 979|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.116 |SIPStationInit: connID=0, SEP001A3F03E0D1, 172.16.1.12:5060, REGISTER Queued|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.116 |SIPStationInit: connID=0, SEP001A3F03E0D1, 172.16.1.12:5060, DevStat-InitState: NEW --> ON_NEWREG_QUEUE|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.117 |//SIP/Stack/Event/0xb4550f50/

ccsip_api_register_ind return value : SIP_SUCCESS

|1,100,213,1.1017^172.16.1.12^*

09:34:35.117 |//SIP/Stack/Info/0xb4550f50/Adding call id 3d3 to table|1,100,213,1.1017^172.16.1.12^*

09:34:35.117 |//SIP/Stack/States/0xb4550f50/0xb4550f50 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE)|1,100,213,1.1017^172.16.1.12^*

09:34:35.222 |SIPStationInit: Processing registration queue|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.222 |SIPStationInit: connID=0, SEP001A3F03E0D1, 172.16.1.12:5060, Creating new SIPStationD|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.222 |SIPRegistrationTable::pidAdd: Adding pid to table via pidAdd [1,100,58,730]:|*^*^*

09:34:35.222 |SIPStationInit: connID=0, SEP001A3F03E0D1, 172.16.1.12:5060, DevStat-InitState: ON_NEWREG_QUEUE --> REGISTERED|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.222 |SIPStationInit: RegQueueSize=0 MaxEntriesToProcess=40 tokeMax=10 tokeOut=0 Registration Queue Serviced 1 entries in 0 milliseconds|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.222 |SIPStationD(1,100,58,730), , UNKNOWN:0, primaryDN=UNKNOWN, Primary expires 120, secondary expires 3600|1,100,58,730.1^*^*

09:34:35.222 |SIPStationD(1,100,58,730), , 172.16.1.12:5060, primaryDN=1015, userStart chars . . 0|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.222 |SIPStationD(1,100,58,730), , 172.16.1.12:5060, primaryDN=1015, getTypeModel: User-Agent header does not indicate Cisco, assuming PREFERRED_VENDOR_UA, useCepnForContact false|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.222 |SIPStationD(1,100,58,730), , 172.16.1.12:5060, primaryDN=1015, wait_register_SIPRegisterInd: model=638, mUaType=6|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.222 |SIPStationD(1,100,58,730), , 172.16.1.12:5060, primaryDN=1015, Register instanceId (MAC addr) =001A3F03E0D1|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.222 |SIPStationD(1,100,58,730), , 172.16.1.12:5060, primaryDN=1015, Register deviceName (database key) =SEP001A3F03E0D1|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.223 |SIPStationD(1,100,58,730), SEP001A3F03E0D1, 172.16.1.12:5060, primaryDN=1015, DevStat-Start : transport UDP, model 638|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.223 |SIPStationD(1,100,58,730), SEP001A3F03E0D1, 172.16.1.12:5060, primaryDN=1015, parseSupportedHeader: X-cisco-callinfo=T X-cisco-serviceuri=T X-cisco-escapecodes=F X-cisco-service-control=T X-cisco-srtp-fallback=F X-cisco-monrec=F X-cisco-xsi=F xsi-version=0.0.0 X-cisco-sis=F sis-version=0.0.0 extended-refer=T norefersub=T join=F cso[rcc=F,sc=F,max=0] slNotify=0 hsNotify=0 blfNotify=0 fi[joinReq=F,cfwdAny=F]|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.223 |SIPStationD(1,100,58,730), SEP001A3F03E0D1, 172.16.1.12:5060, primaryDN=1015, setOptionsIndicationDefaultOptions: INFO - user agent 6|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.223 |CcmdbStationRegistrationProfileBuilder::init - No typemodel table-entry for device SEP001A3F03E0D1.|*^*^*

09:34:35.223 |CcmdbStationRegistrationProfileBuilder::getBasicRegistrationProfile::init() - failed rc(1)|*^*^*

09:34:35.223 |Non-Cisco entity registration lookup failed. Recycling registration to digest challenge the endpoint.|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.223 |SIPStationD(1,100,58,730), SEP001A3F03E0D1, 172.16.1.12:5060, primaryDN=1015, userStart chars . . 0|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.223 |SIPStationD(1,100,58,730), SEP001A3F03E0D1, 172.16.1.12:5060, primaryDN=1015, getTypeModel: User-Agent header does not indicate Cisco, assuming PREFERRED_VENDOR_UA, useCepnForContact false|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.223 |SIPStationD(1,100,58,730), SEP001A3F03E0D1, 172.16.1.12:5060, primaryDN=1015, wait_register_SIPRegisterInd: model=638, mUaType=6|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.223 |SIPStationD(1,100,58,730), SEP001A3F03E0D1, 172.16.1.12:5060, primaryDN=1015, Register instanceId (MAC addr) =001A3F03E0D1|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.223 |SIPStationD(1,100,58,730), SEP001A3F03E0D1, 172.16.1.12:5060, primaryDN=1015, Register deviceName (database key) =NULL|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.223 |SIPStationD(1,100,58,730), SEP001A3F03E0D1, 172.16.1.12:5060, primaryDN=1015, DevStat-Start : transport UDP, model 638|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.223 |SIPStationD(1,100,58,730), SEP001A3F03E0D1, 172.16.1.12:5060, primaryDN=1015, parseSupportedHeader: X-cisco-callinfo=T X-cisco-serviceuri=T X-cisco-escapecodes=F X-cisco-service-control=T X-cisco-srtp-fallback=F X-cisco-monrec=F X-cisco-xsi=F xsi-version=0.0.0 X-cisco-sis=F sis-version=0.0.0 extended-refer=T norefersub=T join=F cso[rcc=F,sc=F,max=0] slNotify=0 hsNotify=0 blfNotify=0 fi[joinReq=F,cfwdAny=F]|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.223 |SIPStationD(1,100,58,730), SEP001A3F03E0D1, 172.16.1.12:5060, primaryDN=1015, setOptionsIndicationDefaultOptions: INFO - user agent 6|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.223 |SIPStationD(1,100,58,730), SEP001A3F03E0D1, 172.16.1.12:5060, primaryDN=1015, Convert UserId "1015" to deviceName|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.223 |SIPStationD(1,100,58,730), SEP001A3F03E0D1, 172.16.1.12:5060, primaryDN=1015, deviceType=638, mSIPAuthorizationHeaderPtr->user_pass=1015|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.223 |DbInfoError - Configuration information may be out of sync for the device and Unified CM database Name of Device:SEP001A3F03E0D1 App ID:Cisco CallManager Cluster ID:StandAloneCluster Node ID:cucm2|AlarmSEP001A3F03E0D1^*^SEP001A3F03E0D1

09:34:35.224 |EndPointTransientConnection - An endpoint attempted to register but did not complete registration Connecting Port:5060 Device name:SEP001A3F03E0D1 Device IP address:172.16.1.12 Protocol:SIP Device type:638 Reason Code:3 Registering SIP User:1015 App ID:Cisco CallManager Cluster ID:StandAloneCluster Node ID:cucm2|AlarmSEP001A3F03E0D1^*^SEP001A3F03E0D1

09:34:35.224 |SIPStationD(1,100,58,730), SEP001A3F03E0D1, 172.16.1.12:5060, primaryDN=1015, Registration profile error: Error: DB Config, sending registration reject and closing station|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.224 |SIPStationD(1,100,58,730), SEP001A3F03E0D1, 172.16.1.12:5060, primaryDN=1015, Phone doesn't support ExtendedRefer, not sending status line update|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.224 |SIPStationD(1,100,58,730), SEP001A3F03E0D1, 172.16.1.12:5060, primaryDN=1015, sendRegisterResp: non-200 response code 404, ccbId 979, expires 4294967295, warning Unable to find device/user in database|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.224 |SIPStationD(1,100,58,730), SEP001A3F03E0D1, 172.16.1.12:5060, primaryDN=1015, DevStat-StopClose: Database error|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.224 |SIPStationD(1,100,58,730), SEP001A3F03E0D1, 172.16.1.12:5060, primaryDN=1015, closeStation: number of outstanding transactional subscriptions = 0, configMismatch = false|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.224 |SIPStationD(1,100,58,730), SEP001A3F03E0D1, 172.16.1.12:5060, primaryDN=1015, closeStation: sending StationCloseRequest, setting state to shutting_down|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.224 |SIPStationInit: connID=0, SEP001A3F03E0D1, 172.16.1.12:5060, DevStat-InitState: REGISTERED --> STATION_CLOSE_REQ_RCVD|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.224 |SIPStationInit: connID=0, SEP001A3F03E0D1, 172.16.1.12:5060, StationCloseReq: remove bindings, closeConn=1|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.224 |SIPStationInit: connID=0, SEP001A3F03E0D1, 172.16.1.12:5060, Removing targetEntry|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.224 |SIPStationInit: connID=0, SEP001A3F03E0D1, 172.16.1.12:5060, DevStat-InitState: STATION_CLOSE_REQ_RCVD --> DELETING|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.224 |SIPStationInit: Sending StationClose to the D|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.224 |//SIP/Stack/Info/0x0/ccsip_spi_get_msg_type returned: 3 for event 42|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.224 |//SIP/Stack/Info/0xb4550f50/Associated container=0xb43ed150 to REGISTER Response 404|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.224 |//SIP/Stack/Transport/0xb4550f50/Sending INFO Response to the transport layer|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.224 |//SIP/Stack/Transport/0xb4550f50/msg=0xb45a1e70, addr=172.16.1.12, port=5060, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=0xa106e72|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.224 |//SIP/Stack/Transport/0xb4550f50/Proceedable for sending msg immediately|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.224 |//SIP/Stack/Transport/0xb4550f50/switch transport is 0|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.224 |//SIP/Stack/Transport/0x0/Posting send for msg=0xb45a1e70, addr=172.16.1.12, port=5060, connId=0 for UDP|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.224 |//SIP/SIPHandler/ccbId=0/scbId=0/sip_stop_timer: type=SIP_TIMER_REMOVE_TRANSACTION value=32000 retries=0|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.225 |//SIP/SIPHandler/ccbId=0/scbId=0/sip_start_timer: type=SIP_TIMER_REMOVE_TRANSACTION value=32000 retries=0|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.225 |//SIP/Stack/States/0xb4550f50/0xb4550f50 : State change from (SIP_STATE_INCOMING_REGISTER, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

09:34:35.225 |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.16.1.12:[5060]:

SIP/2.0 404 Not Found

Via: SIP/2.0/UDP 172.16.1.12:5060;rport;branch=z9hG4bKFI03h1-jsACr07Ki

From: 1015<sip:1015@172.16.1.202>;tag=RzJ3h1-a47OG

To: 1015<sip:1015@172.16.1.202>;tag=400216712

Date: Fri, 01 Mar 2013 13:34:35 GMT

Call-ID: 7joPS0-dX*B33h1@172.16.1.202

CSeq: 125 REGISTER

Warning: 399 cucm2 "Unable to find device/user in database"

Content-Length: 0

|1,100,213,1.1017^172.16.1.12^SEP001A3F03E0D1

acampbell · ‎03-01-2013

Antonio,

Have you added the

Digest user to the phone

In the Digest User field of the Phone Configuration window, choose the end user that you created in

Regards,
Alex.
Please rate useful posts.

Regards, Alex. Please rate useful posts.

Antonio Brandao · ‎03-01-2013

Yes Alex,

I did setup Digest user and linked in Device setup on call manager. I did some changes again and now I´m getting follow output

|1,100,213,1.2925^172.16.1.12^SEP001A3F03E0D1

14:02:38.887 |//SIP/Stack/Info/0x0/ccsip_spi_get_msg_type returned: 2 for event 1|1,100,213,1.2925^172.16.1.12^SEP001A3F03E0D1

14:02:38.888 |//SIP/Stack/Transport/0x0/context=(nil)|1,100,213,1.2925^172.16.1.12^SEP001A3F03E0D1

14:02:38.888 |//SIP/Stack/Info/0x0/Checking Invite Dialog|1,100,213,1.2925^172.16.1.12^SEP001A3F03E0D1

14:02:38.888 |//SIP/Stack/Info/0xb45746f0/*****CCB found in UAS Request table. ccb=0xb45746f0|1,100,213,1.2925^172.16.1.12^SEP001A3F03E0D1

14:02:38.888 |//SIP/Stack/Transport/0x0/Subsq Transaction Address 172.16.1.12,Port 5060, Transport 1, SentBy Port 5060|1,100,213,1.2925^172.16.1.12^SEP001A3F03E0D1

14:02:38.888 |//SIP/Stack/Info/0xb45746f0/REGISTER request pending|1,100,213,1.2925^172.16.1.12^SEP001A3F03E0D1

14:02:38.888 |//SIP/Stack/Info/0xb45746f0/Response Container Holder is above threshold...trimming|1,100,213,1.2925^172.16.1.12^SEP001A3F03E0D1

14:02:38.888 |//SIP/Stack/Transport/0xb45746f0/Sending INFO Response to the transport layer|1,100,213,1.2925^172.16.1.12^SEP001A3F03E0D1

14:02:38.888 |//SIP/Stack/Transport/0xb45746f0/msg=0xb45a21c8, addr=172.16.1.12, port=5060, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=(nil)|1,100,213,1.2925^172.16.1.12^SEP001A3F03E0D1

14:02:38.888 |//SIP/Stack/Transport/0xb45746f0/Proceedable for sending msg immediately|1,100,213,1.2925^172.16.1.12^SEP001A3F03E0D1

14:02:38.888 |//SIP/Stack/Transport/0xb45746f0/switch transport is 0|1,100,213,1.2925^172.16.1.12^SEP001A3F03E0D1

14:02:38.888 |//SIP/Stack/Transport/0x0/Posting send for msg=0xb45a21c8, addr=172.16.1.12, port=5060, connId=0 for UDP|1,100,213,1.2925^172.16.1.12^SEP001A3F03E0D1

14:02:38.888 |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.16.1.12:[5060]:

SIP/2.0 100 Trying

Via: SIP/2.0/UDP 172.16.1.12:5060;rport;branch=z9hG4bKFI03h1-TTWTeZ4i

From: 1015<1015>;tag=RzJ3h1-DJRX5

To: 1015<1015>;tag=201397974

Date: Fri, 01 Mar 2013 18:02:38 GMT

Call-ID: r73vz-BM*B33h1@172.16.1.202

CSeq: 409 REGISTER

Content-Length: 0

Ayodeji Okanlawon · ‎03-01-2013

Hi,

Your trace is incomplete. We need to see what happens after cucm sent the trying. Pls send full logs

Sent from Cisco Technical Support Android App

Please rate all useful posts

Antonio Brandao · ‎03-04-2013

I was running this CM in a Virtual enviromente, I did restart it seems the SIP phone is working now :S

Thanks for all your help.

Antonio

asharsidd · ‎06-17-2014

Hello,

I know this an year old issue but thought to answer it for the benefit of someone else who may stumble upon this thread.

I had a similar issue for CUCM 9.1.2 and phone was 7841 SIP. The issue was that phone was registering and then unregistering. Looking at the logs from Pub and Sub gave me an hint that the phone is actually registering only with Pub briefly before trying to register with Sub. In Device Pool > Call Manager group> Sub was Primary Call manager so this is why it was briefly registering with Pub and then going for Sub and getting rejected.

In logs of Sub I found similar to what you see above.

08:31:40.497 |AppInfo |CcmdbStationRegistrationProfileBuilder::init - No typemodel table-entry for device SEP544A003629FD.

08:31:40.497 |AppInfo |CcmdbStationRegistrationProfileBuilder::getBasicRegistrationProfile::init() - failed rc(1)

8:31:40.497 |AppInfo |SIPStationD(684) - Registration profile error: Database error, sending registration reject and closing station

08:31:40.497 |AppInfo |SIPStationD(684) - sendRegisterResp: non-200 response code 404, ccbId 336776, expires 4294967295, warning Database error

8:31:40.497 |AppInfo |EndPointTransientConnection - An endpoint attempted to register but did not complete registration Connecting Port:5060 Device name:SEP544A003629FD Device IP address:172.18.52.91 Device type:622 Reason Code:30 Protocol:SIP Device MAC address:544A003629FD IPAddressAttributes:0 LastSignalReceived:SIPRegisterInd StationState:wait_register App ID:Cisco CallManager Cluster ID:StandAloneCluster Node ID:gc49cucm2

.

Here the No typemodel is the important bit. This only happens when Call manager does not support your phone type or if you have applied a device pack you have not applied on all nodes or you may have applied device pack on all nodes but did not restart the whole cluster. In my issue it was the last case where customer applied Device pack on all nodes but only restarted Pub and this is why Sub could not see that device type and phone was registering with Pub.

Hope this helps.