Setup:
2-server cluster
CUCM 12.0.1.10000-10
Database replication is clean
Phones being converted are phones that are in production but using SCCP
All of the 7941s, 7942s, 7961s, and 7962s converted successfully and downloaded their configs successfully. Only 7940s and 7960s are having issues.
There are no firewalls, ACLs, etc between the phones and the CUCMs. The capture/logs below are from when I tested with the Sub, which is in a different subnet but I get the same if I do this with the Pub, which is in the same subnet/VLAN as the phones I'm testing with.
We have to convert all of our SCCP phones to SIP to accommodate a SIP-only recording software. These older models are on track to be replaced in the next year or so, but we still have to make them work until they get replaced
I am able to successfully convert a 7940 or 7960 to SIP firmware without incident. The problem is that when it goes to request its config file from CUCM, it is told that the file is not found.
I have verified both from packet captures taken on the CUCM and from trace logs of the TFTP service that this is what's happening. The phone correctly requests its configuration file and the TFTP service says the file doesn't exist.
I can browse to the file using http://<CUCM IP>:6970/SIP<MAC>.cnf so I know that the file exists on the Call Manager. If I move this file to my laptop and set up a TFTP server on my laptop I can point the phone to my laptop for TFTP and the phone will successfully download the file from my laptop and register to CUCM.
The issue occurs regardless of whether I set the Pub or Sub as the Option 150 target. TFTP logs show the same errors.
Below are the logs that I'm seeing. Anyone have any thoughts on what is going on and why this would only affect 7940s and 7960s?
10.25.142.5 = CUCM
10.25.101.55 = PHONE
0012006820E5 = PHONE MAC
Packet Capture:
SEE ATTACHED SCREENSHOT
TFTP Log:
00000414.000 |12:09:44.747 |AppInfo | TID[d4720b70] TFTPEngine::getRequest[0xf510d2c0](), server socket(74) INFO:: File Requested CTLSEP0012006820E5.tlv
00000415.000 |12:09:44.747 |SdlStat |Period: 1693s #Lines: 2 #Bytes: 315 Total Number of Buffers: 2000 Free LWM: 1998 Free LWM(total): 1938
00000416.000 |12:09:44.770 |AppInfo |INFO: TFTPEngine::sendNAK[0xf510d2c0~0~10.25.101.55~50604], File[CTLFile.tlv], Error(1)
00000417.000 |12:09:44.792 |AppInfo | TID[d4720b70] TFTPEngine::getRequest[0xf511ffb0](), server socket(74) INFO:: File Requested SEP0012006820E5.cnf.xml
00000418.000 |12:09:44.793 |AppInfo |CTFTPDB_DeviceVersionRecords::loadRecords(), For DeviceId[9eb830b5-f40f-30c9-3b19-8c5cc97c0393] *** commondeviceconfig Record[] Not Found ***
00000419.000 |12:09:44.806 |AppInfo |INFO: TFTPEngine::sendNAK[0xf511ffb0~1~10.25.101.55~50605], File[SEP0012006820E5.cnf.xml], Error(1)
00000420.000 |12:09:44.806 |AppInfo |CTFTPDB_DeviceVersionRecords::loadRecords(), For DeviceId[9eb830b5-f40f-30c9-3b19-8c5cc97c0393] *** commondeviceconfig Record[] Not Found ***
00000421.000 |12:09:44.808 |AppInfo |INFO: TFTPEngine::sendNAK[0xf511ffb0~1~10.25.101.55~50605], File[SEP0012006820E5.cnf.xml.sgn], Error(1)
00000422.000 |12:09:44.808 |AppInfo |INFO: TFTPEngine::sendNAK[0xf511ffb0~1~10.25.101.55~50605], File[SEP0012006820E5.cnf.xml], Error(1)
00000423.000 |12:09:44.836 |AppInfo | TID[d4720b70] TFTPEngine::getRequest[0xf51209b0](), server socket(74) INFO:: File Requested SIP0012006820E5.cnf
00000424.000 |12:09:44.840 |AppInfo |INFO: TFTPEngine::sendNAK[0xf51209b0~2~10.25.101.55~50606], File[SIP0012006820E5.cnf], Error(1)
00000425.000 |12:09:44.860 |AppInfo | TID[d4720b70] TFTPEngine::getRequest[0xf51213b0](), server socket(74) INFO:: File Requested MGC0012006820E5.cnf
00000426.000 |12:09:44.860 |AppInfo |INFO: TFTPEngine::sendNAK[0xf51213b0~3~10.25.101.55~50607], File[MGC0012006820E5.cnf], Error(1)
00000427.000 |12:09:44.880 |AppInfo | TID[d4720b70] TFTPEngine::getRequest[0xf5121db0](), server socket(74) INFO:: File Requested XMLDefault.cnf.xml
00000428.000 |12:09:45.053 |AppInfo |TFTPEngine::processMessage[0xf5121db0~4~10.25.101.55~50608], Unexpected Opcode[5] Expecting ACK Block[17], Socket[13] FileName[XMLDefault.cnf.xml], th_block [11] Abort...
00000429.000 |12:09:45.070 |AppInfo | TID[d4720b70] TFTPEngine::getRequest[0xf51227b0](), server socket(74) INFO:: File Requested SIPDefault.cnf
00000430.000 |12:09:45.075 |AppInfo |TID[d7925b70] INFO: TFTPEngine::processMessage[0xf51227b0~5~10.25.101.55~50609], Transferred[SIPDefault.cnf] Socket[13]
00000431.000 |12:09:55.628 |AppInfo | TID[d4720b70] TFTPEngine::getRequest[0xf51231b0](), server socket(74) INFO:: File Requested SIPDefault.cnf
00000432.000 |12:09:55.628 |SdlStat |Period: 11s #Lines: 16 #Bytes: 2468 Total Number of Buffers: 2000 Free LWM: 1998 Free LWM(total): 1938
00000433.000 |12:09:55.634 |AppInfo |TID[d7925b70] INFO: TFTPEngine::processMessage[0xf51231b0~6~10.25.101.55~49992], Transferred[SIPDefault.cnf] Socket[13]
00000434.000 |12:09:55.813 |AppInfo | TID[d4720b70] TFTPEngine::getRequest[0xf5123bb0](), server socket(74) INFO:: File Requested SIP0012006820E5.cnf
00000435.000 |12:09:55.813 |AppInfo |INFO: TFTPEngine::sendNAK[0xf5123bb0~7~10.25.101.55~49993], File[SIP0012006820E5.cnf], Error(1)
00000436.000 |12:09:58.032 |AppInfo | TID[d4720b70] TFTPEngine::getRequest[0xf51245b0](), server socket(74) INFO:: File Requested RINGLIST.DAT
00000437.000 |12:09:58.047 |AppInfo |TID[d7925b70] INFO: TFTPEngine::processMessage[0xf51245b0~8~10.25.101.55~50000], Transferred[RingList.DAT] Socket[13]
