[cisco-voip] CME registration issue

Leslie Meade Leslie.Meade at lvs1.com
Fri Jun 8 00:55:27 EDT 2012 

I have a strange issue that I think I know the issue but do not know how to fix it.

I have a test lab and today I fired up my PSTN router a 3745, and for the past year it was worked with out an issue.
But today i am getting the phone hanging at "requesting Softkey Template" then it will cycle through again

There has been no changes to the router. When i do a debug tftp events i get the  following

Jun  7 21:35:57.695: New Skinny socket accepted [1] (1 active)
Jun  7 21:35:57.695: sin_family 2, sin_port 50667, in_addr 10.10.200.21
Jun  7 21:35:57.695: skinny_add_socket 1 10.10.200.21 50667
Jun  7 21:35:57.703: %IPPHONE-6-REG_ALARM: 17: Name=SEP0014F26A78CA Load=8.0(9.0) Last=KeepaliveTO
Jun  7 21:35:57.703: ephone-(3)[2] StationRegisterMessage (1/1/5) from 10.10.200.21
Jun  7 21:35:57.703: ephone-(3)[2] Register StationIdentifier DeviceName SEP0014F26A78CA
Jun  7 21:35:57.703: ephone-(3)[2] StationIdentifier Instance 1    deviceType 7
Jun  7 21:35:57.703: ephone-3[1]:stationIpAddr 10.10.200.21
Jun  7 21:35:57.703: ephone-3[1][SEP0014F26A78CA]:maxStreams 0
Jun  7 21:35:57.703: ephone-3[1][SEP0014F26A78CA]:From Phone raw protocol Ver 0x8560000B
Jun  7 21:35:57.703: ephone-3[1][SEP0014F26A78CA]:protocol Ver 0x8560000B
Jun  7 21:35:57.703: ephone-3[1][SEP0014F26A78CA]:phone-size 5480 dn-size 688
Jun  7 21:35:57.703: ephone-(3) Allow any Skinny Server IP address 10.10.250.2
Jun  7 21:35:57.703: ephone-3[1][SEP0014F26A78CA]:Found entry 2 for 0014F26A78CA
Jun  7 21:35:57.703: ephone-3[1][SEP0014F26A78CA]:socket change 1 to 2
Jun  7 21:35:57.703: ephone-3[1][SEP0014F26A78CA]:DisAssociate: Closed socket 1 while REGISTERED
Jun  7 21:35:57.707: %IPPHONE-6-UNREGISTER_ABNORMAL: ephone-3:SEP0014F26A78CA IP:10.10.200.21 Socket:1 DeviceType:Phone has unregistered abnormally.
Jun  7 21:35:57.707: ephone-3[-1][SEP0014F26A78CA]:FAILED: CLOSED old socket -1
Jun  7 21:35:57.707: ephone-3[2][SEP0014F26A78CA]:***Force device subtype to 0
Jun  7 21:35:57.707: ephone-3[2][SEP0014F26A78CA]:phone SEP0014F26A78CA re-associate OK on socket [2]
Jun  7 21:35:57.707: %IPPHONE-6-REGISTER: ephone-3:SEP0014F26A78CA IP:10.10.200.21 Socket:2 DeviceType:Phone has registered.
Jun  7 21:35:57.707: Phone 2 socket 2
Jun  7 21:35:57.707: Skinny Local IP address = 10.10.250.2 on port 2000
Jun  7 21:35:57.707: Skinny Phone IP address = 10.10.200.21 50667
Jun  7 21:35:57.707: ephone-3[2][SEP0014F26A78CA]:Signal protocol ver 8 to phone with ver 11
Jun  7 21:35:57.707: ephone-3[2][SEP0014F26A78CA]:Date Format M/D/Y
Jun  7 21:35:57.707: ephone-3[2]:RegisterAck sent to sockettype ephone socket 2: keepalive period 30 use sccp-version 8
Jun  7 21:35:57.707: ephone-3[2]:CapabilitiesReq sent
Jun  7 21:35:57.715: ephone-3[2]:MediaPathEventMessage
Jun  7 21:35:57.715: ephone-3[2]:MediaPathEventMessage
Jun  7 21:35:57.719: ephone-3[2]:MediaPathEventMessage
Jun  7 21:35:57.755: ephone-3[2]:MediaPathEventMessage
Jun  7 21:35:57.759: ephone-3[2]:MediaPathEventMessage
Jun  7 21:35:57.919: ephone-3[2]:CapabilitiesRes received
Jun  7 21:35:57.919: ephone-3[2][SEP0014F26A78CA]:Caps list 8
WideBand_256K  120 ms
G711Ulaw64k  40 ms
G711Alaw64k  40 ms
G729AnnexB  60 ms
G729AnnexAwAnnexB  60 ms
G729  60 ms
G729AnnexA  60 ms
Unrecognized Media Type 257  4 ms
Jun  7 21:35:57.919: ephone-3[2]:MediaPathEventMessage
Jun  7 21:35:57.919: ephone-3[2]:MediaPathEventMessage
Jun  7 21:35:57.919: ephone-3[2]:ButtonTemplateReqMessage
Jun  7 21:35:57.919: ephone-3[2][SEP0014F26A78CA]:StationButtonTemplateReqMessage set max presentation to 6
Jun  7 21:35:57.919: ephone-3[2]:CheckAutoReg
Jun  7 21:35:57.919: ephone-3[2]:AutoReg is disabled
Jun  7 21:35:57.919: ephone-3[2][SEP0014F26A78CA]:Setting 6 lines 0 speed-dials on phone (max_line 6)
Jun  7 21:35:57.919: ephone-3[2][SEP0014F26A78CA]:First Speed Dial Button location is 0 (0)
Jun  7 21:35:57.919: ephone-3[2][SEP0014F26A78CA]:Configured 0 speed dial buttons
Jun  7 21:35:57.919: ephone-3[2]:ButtonTemplate lines=6 speed=0 buttons=6 offset=0
Jun  7 21:35:57.927: ephone-3[2]:StationSoftKeyTemplateReqMessage
Jun  7 21:35:57.927: ephone-3[2]:StationSoftKeyTemplateResMessage  <-- This is where the Requesting Softkey Template hangs
Jun  7 21:35:58.115: Bring up DN 1 by SkinnyCheckDnStatus
Jun  7 21:35:58.591: TFTP: Finished system:/its/XMLDefault7960.cnf.xml, time 00:00:25 for process 154
Jun  7 21:35:59.115: Bring up DN 2 by SkinnyCheckDnStatus
Jun  7 21:36:00.115: Bring up DN 3 by SkinnyCheckDnStatus
Jun  7 21:36:01.115: Bring up DN 4 by SkinnyCheckDnStatus
Jun  7 21:36:02.115: Bring up DN 5 by SkinnyCheckDnStatus
Jun  7 21:36:02.623: TFTP: Finished system:/its/XMLDefault7960.cnf.xml, time 00:00:25 for process 156
Jun  7 21:36:03.115: Bring up DN 6 by SkinnyCheckDnStatus
Jun  7 21:36:06.619: TFTP: Finished system:/its/XMLDefault7960.cnf.xml, time 00:00:25 for process 171
Jun  7 21:36:07.115: ephone-3[2]:SkinnyCompleteRegistration
Jun  7 21:36:10.619: TFTP: Finished system:/its/XMLDefault7960.cnf.xml, time 00:00:25 for process 184
Jun  7 21:36:14.619: TFTP: Finished system:/its/XMLDefault7960.cnf.xml, time 00:00:25 for process 238
Jun  7 21:36:18.619: TFTP: Finished system:/its/XMLDefault7960.cnf.xml, time 00:00:25 for process 81
Jun  7 21:37:32.679: ephone-3[2][SEP0014F26A78CA]:Phone Unregistered on socket [2] SEP0014F26A78CA
Jun  7 21:37:33.115: Bring up DN 6 by SkinnyCheckDnStatus
Jun  7 21:37:34.115: Bring up DN 1 by SkinnyCheckDnStatus
Jun  7 21:37:35.115: Bring up DN 2 by SkinnyCheckDnStatus
Jun  7 21:37:36.115: Bring up DN 3 by SkinnyCheckDnStatus
Jun  7 21:37:40.115: Bring up DN 4 by SkinnyCheckDnStatus
Jun  7 21:37:41.115: Bring up DN 5 by SkinnyCheckDnStatus


the system reports that the phone is registered

ephone-3 Mac:0014.F26A.78CA TCP socket:[1] activeLine:0 REGISTERED in SCCP ver 11 and Server in ver 8
mediaActive:0 offhook:0 ringing:0 reset:0 reset_sent:0 paging 0 debug:0 caps:8
IP:10.10.200.21 50668 Telecaster 7960  keepalive 3 max_line 6
button 1: dn 1  number 911 CH1   IDLE         CH2   IDLE
button 2: dn 2  number 2024678124 CH1   IDLE         CH2   IDLE
button 3: dn 3  number 4088397263 CH1   IDLE         CH2   IDLE
button 4: dn 4  number 02077966596 CH1   DOWN
button 5: dn 5  number 2123942123 CH1   DOWN
button 6: dn 6  number 916745738932 CH1   IDLE


Any ideas ?

More information about the cisco-voip mailing list