SPA504G not registering with UC560

ericdolton · ‎05-26-2010

I have SPA504G not finding its cnf file for some reason. Its across a VPN, the phone was registered successfully at the headend. Theres full connectivity over the VPN back and forth. I do a debug tftp packets on the UC560 and get this output. I've already reset the phone to factory default just in case. Anyone seen this before? Or have any other relavant debugs i can run. I don't see any traffic being blocked on any interfaces.

000704: May 26 17:55:10.780: TFTP: Sending block 1 (retry 1), socket_id 0x85E0B5AC
000705: May 26 17:55:12.780: TFTP: Server request for port 1024, socket_id 0x8802493C for process 181
000706: May 26 17:55:12.780: TFTP: read request from host 192.168.1.124(1024) via FastEthernet0/0
000707: May 26 17:55:12.780: TFTP: Looking for SEP8843E1551D59.cnf.xml
000708: May 26 17:55:12.780: TFTP: Opened system:/its/XMLDefault504G.cnf.xml, fd 14, size 1191 for process 181
000709: May 26 17:55:12.780: TFTP: Sending block 1 (retry 0), socket_id 0x8802493C
000710: May 26 17:55:12.780: TFTP: Finished system:/its/XMLDefault504G.cnf.xml, time 00:00:25 for process 222
000711: May 26 17:55:14.780: TFTP: Sending block 1 (retry 3), socket_id 0x8983A3B4
000712: May 26 17:55:14.780: TFTP: Sending block 1 (retry 2), socket_id 0x85E0B5AC
000713: May 26 17:55:15.780: TFTP: Sending block 1 (retry 4), socket_id 0x85E0F93C
000714: May 26 17:55:15.780: TFTP: Sending block 1 (retry 1), socket_id 0x8802493C
000715: May 26 17:55:17.776: TFTP: Server request for port 1024, socket_id 0x8983E6B0 for process 222
000716: May 26 17:55:17.776: TFTP: read request from host 192.168.1.124(1024) via FastEthernet0/0
000717: May 26 17:55:17.776: TFTP: Looking for SEP8843E1551D59.cnf.xml
000718: May 26 17:55:17.780: TFTP: Opened system:/its/XMLDefault504G.cnf.xml, fd 15, size 1191 for process 222
000719: May 26 17:55:17.780: TFTP: Sending block 1 (retry 0), socket_id 0x8983E6B0
000720: May 26 17:55:17.780: TFTP: Finished system:/its/XMLDefault504G.cnf.xml, time 00:00:25 for process 243
000721: May 26 17:55:19.780: TFTP: Sending block 1 (retry 3), socket_id 0x85E0B5AC
000722: May 26 17:55:19.780: TFTP: Sending block 1 (retry 2), socket_id 0x8802493C
000723: May 26 17:55:20.780: TFTP: Sending block 1 (retry 4), socket_id 0x8983A3B4
000724: May 26 17:55:20.780: TFTP: Sending block 1 (retry 1), socket_id 0x8983E6B0
000725: May 26 17:55:22.776: TFTP: Server request for port 1024, socket_id 0x86CC6DE4 for process 243
000726: May 26 17:55:22.776: TFTP: read request from host 192.168.1.124(1024) via FastEthernet0/0
000727: May 26 17:55:22.776: TFTP: Looking for SEP8843E1551D59.cnf.xml
000728: May 26 17:55:22.780: TFTP: Opened system:/its/XMLDefault504G.cnf.xml, fd 16, size 1191 for process 243
000729: May 26 17:55:22.780: TFTP: Sending block 1 (retry 0), socket_id 0x86CC6DE4
000730: May 26 17:55:22.780: TFTP: Finished system:/its/XMLDefault504G.cnf.xml, time 00:00:25 for process 244
000731: May 26 17:55:24.780: TFTP: Sending block 1 (retry 3), socket_id 0x8802493C
000732: May 26 17:55:24.780: TFTP: Sending block 1 (retry 2), socket_id 0x8983E6B0
000733: May 26 17:55:25.780: TFTP: Sending block 1 (retry 4), socket_id 0x85E0B5AC
000734: May 26 17:55:25.780: TFTP: Sending block 1 (retry 1), socket_id 0x86CC6DE4
000735: May 26 17:55:27.776: TFTP: Server request for port 1024, socket_id 0x85E0F93C for process 244
000736: May 26 17:55:27.776: TFTP: read request from host 192.168.1.124(1024) via FastEthernet0/0
000737: May 26 17:55:27.776: TFTP: Looking for SEP8843E1551D59.cnf.xml
000738: May 26 17:55:27.780: TFTP: Opened system:/its/XMLDefault504G.cnf.xml, fd 17, size 1191 for process 244
000739: May 26 17:55:27.780: TFTP: Sending block 1 (retry 0), socket_id 0x85E0F93C
000740: May 26 17:55:27.780: TFTP: Finished system:/its/XMLDefault504G.cnf.xml, time 00:00:25 for process 294
000741: May 26 17:55:29.780: TFTP: Sending block 1 (retry 3), socket_id 0x8983E6B0
000742: May 26 17:55:29.780: TFTP: Sending block 1 (retry 2), socket_id 0x86CC6DE4
000743: May 26 17:55:30.780: TFTP: Sending block 1 (retry 4), socket_id 0x8802493C
000744: May 26 17:55:30.780: TFTP: Sending block 1 (retry 1), socket_id 0x85E0F93C

ephone-10[9] Mac:8843.E155.1D59 TCP socket:[-1] activeLine:0 whisperLine:0 UNREGISTERED
mediaActive:0 whisper_mediaActive:0 startMedia:0 offhook:0 ringing:0 reset:0 reset_sent:0 debug:0 primary_dn: 11
IP:0.0.0.0 Unknown 0 keepalive 0 music 0

ephone 10
device-security-mode none
video
mac-address 8843.E155.1D59
ephone-template 16
max-calls-per-button 2
username
type 504G
button 1:11

Steven DiStefano · ‎05-26-2010

Just tried one. I have a sidecar on mine....

You have alot of retries....

Do you show the load installed on CCA Phone Load Manager for this phone?

Did you just recently upgrade from an older IOS to a recent one (there is a tip if you did)?

UC540#
018378: May 26 18:30:16.038: %LINEPROTO-5-UPDOWN: Line protocol on Interface FastEthernet0/1/4, changed state to up
018379: May 26 18:30:18.530: %IPPHONE-6-REGISTER: ephone-14:SEP0018B9FFD9AF IP:10.1.1.29 Socket:32 DeviceType:Tapi Client has registered.
018380: May 26 14:30:20.562: TFTP: Looking for SEP0018B9FFD9AF.cnf.xml
018381: May 26 14:30:21.734: TFTP: Opened system:/its/XMLDefault504G-500S-1.cnf.xml, fd 13, size 1822 for process 339
018382: May 26 14:30:21.754: TFTP: Finished system:/its/XMLDefault504G-500S-1.cnf.xml, time 00:00:00 for process 339
018383: May 26 14:30:21.766: TFTP: Looking for spa5x5-7-4-3.BIN
018384: May 26 14:30:21.770: TFTP: Opened flash:/phones/5x5/spa5x5-7-4-3.bin, fd 13, size 3485774 for process 339
018385: May 26 14:30:21.794: TFTP: Looking for RingList.xml
018386: May 26 14:30:21.802: TFTP: Opened flash:/ringtones/RingList.xml, fd 14, size 2823 for process 340
018387: May 26 14:30:21.818: TFTP: Finished flash:/ringtones/RingList.xml, time 00:00:00 for process 340
018388: May 26 14:30:21.830: TFTP: Looking for DistinctiveRingList.xml
018389: May 26 14:30:21.838: TFTP: Opened flash:/ringtones/DistinctiveRingList.xml, fd 14, size 2823 for process 340
018390: May 26 14:30:21.858: TFTP: Finished flash:/ringtones/DistinctiveRingList.xml, time 00:00:00 for process 340
018391: May 26 14:30:21.870: TFTP: Looking for Ring7.raw
018392: May 26 14:30:21.874: TFTP: Opened flash:/ringtones/Ring7.raw, fd 14, size 4000 for process 340
018393: May 26 14:30:21.902: TFTP: Finished flash:/ringtones/Ring7.raw, time 00:00:00 for process 340
018394: May 26 14:30:21.910: TFTP: Looking for Ring5.raw
018395: May 26 14:30:21.910: TFTP: Opened flash:/ringtones/Ring5.raw, fd 14, size 4000 for process 341
018396: May 26 14:30:21.942: TFTP: Finished flash:/ringtones/Ring5.raw, time 00:00:00 for process 341
018397: May 26 14:30:22.014: TFTP: Looking for English_United_States/504-dictionary.xml
018398: May 26 14:30:22.106: TFTP: Looking for English_United_States/SCCP-dictionary.xml
018399: May 26 14:30:22.106: TFTP: Opened system:/its/united_states/SCCP-dictionary.xml, fd 14, size 2740 for process 340
018400: May 26 14:30:22.122: TFTP: Finished system:/its/united_states/SCCP-dictionary.xml, time 00:00:00 for process 340
018401: May 26 14:30:22.202: TFTP: Looking for English_United_States/SCCP-dictionary.xml
018402: May 26 14:30:22.202: TFTP: Opened system:/its/united_states/SCCP-dictionary.xml, fd 14, size 2740 for process 340
018403: May 26 14:30:22.218: TFTP: Finished system:/its/united_states/SCCP-dictionary.xml, time 00:00:00 for process 340

ericdolton · ‎08-25-2010

The solution turned out to be related to the ip tftp source-interface command referencing the loopback interface which was not included as interesting vpn traffic. So the phone, which was at another end of a vpn tunnel, could not revieve any tftp traffic