01-23-2014 05:04 AM - edited 03-16-2019 09:23 PM
In one of customer's CUCM V 9.1, total tftp reqests and total tftp requested aborted are increasing so quickly inRTMT. e.g. last month 'total tftp requested aborted' count was near about 9 lakhs and now it 11 lakhs morover customer has not observed any issue in their ip telephony devices.
What could be reason behind it, can someone please help me to find out the exact cause for it. Thanks in advance !!!
Regards,
Suresh
01-23-2014 05:20 AM
You can grab TFTP logs probably you need to enable this in Detailed so that detailed information can be capture.
You can check the devices or ip address from where you can getting aborted then further check below process.
The the total number of TFTP request that were cancelled(aborted) unexpectedly by the server. request can also be aborted if the requesting device cannot be reached for instance that devices is shut or lost power etc.. or if the file transfer is getting interrupted due to some network connectivity problems.
Br,
Nadeem
Please rate all useful post.
01-23-2014 05:30 AM
Hi Suresh,
Common reasons for this are that certain VG224, VG248, ATAs may be trying to retrieve the config file from tftp which could be triggering the TFTP Requests Aborted. This is an issue if the ports for above devices are either not configured or are misconfigured causing them to contact TFTP repeatedly. Besides ther can be some IP phones stuck in a loop trying to download config file or in some cases the ITL file from TFTP server. Try to identify some IP addresses that are repeated in the logs and check their config.
HTH
Manish
01-24-2014 05:07 AM
Thanks a lot Manish and Nadeem for the quick response, but I need small more clarification, actually today I have collected TFTP logs and found something related to my issue, but I doubt which one of below error increase the total tftp requested aborted any why ?
CTFTPDB_DeviceVersionRecords::loadRecords(), For DeviceId[a6b4a735-bdce-9e31-2564-2035accc5a8e] *** commondeviceconfig Record[] Not Found ***
TID[9e514b90] TFTPEngine::CheckStaleRequests(),[0xd1921e8~156~10.204.25.218~45773] Aborting after [1] Retries. Socket[16] Serving File[SEP34A84E614F02.cnf.xml.sgn] Initial Packet#[1]
TID[9e514b90] TFTPEngine::CheckStaleRequests(),[0xd193f88~159~10.204.25.218~43256] Aborting after [1] Retries. Socket[16] Serving File[XMLDefault.cnf.xml.sgn] Initial Packet#[1]
And below is a part of full tftp logs.
00519755.000 |00:00:07.239 |FileHead |Date: 2014/01/24, AppName: Cluster, AppId: 600, AppNodeId: 1, AppVersion: 0.1, HostName: CiscoCUCMPUB, HostIPAddress: 10.10.25.25, AppStartTime: 2013/05/21 13:42:32, FileNumber: 268, TraceVer: 3.0
00519756.000 |00:00:07.239 |SdlSig |AuditTimer |wait |Audit(1,600,19,1) |SdlTimerService(1,600,3,1) |1,600,26,1.1^*^* |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0]
00519757.000 |00:00:07.239 |SdlStat |Period: 469s #Lines: 3 #Bytes: 583 Total Number of Buffers: 2000 Free LWM: 1997 Free LWM(total): 1934
00519758.000 |00:10:07.383 |SdlSig |AuditTimer |wait |Audit(1,600,19,1) |SdlTimerService(1,600,3,1) |1,600,26,1.1^*^* |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0]
00519759.000 |00:10:07.383 |SdlStat |Period: 600s #Lines: 1 #Bytes: 252 Total Number of Buffers: 2000 Free LWM: 1998 Free LWM(total): 1934
00519760.000 |00:14:30.563 |AppInfo |CTFTPDB_DeviceVersionRecords::loadRecords(), For DeviceId[a9361912-fc53-11b5-5cfd-2f336ec439de] *** commondeviceconfig Record[] Not Found ***
00519761.000 |00:14:30.563 |SdlStat |Period: 263s #Lines: 1 #Bytes: 182 Total Number of Buffers: 2000 Free LWM: 1998 Free LWM(total): 1934
00519762.000 |00:14:30.565 |AppInfo | TID[0962eb90] signTFTPFile(..) Signature Size:128
00519763.000 |00:20:07.538 |SdlSig |AuditTimer |wait |Audit(1,600,19,1) |SdlTimerService(1,600,3,1) |1,600,26,1.1^*^* |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0]
00519764.000 |00:20:07.538 |SdlStat |Period: 337s #Lines: 2 #Bytes: 344 Total Number of Buffers: 2000 Free LWM: 1997 Free LWM(total): 1934
00519765.000 |00:30:07.690 |SdlSig |AuditTimer |wait |Audit(1,600,19,1) |SdlTimerService(1,600,3,1) |1,600,26,1.1^*^* |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0]
00519766.000 |00:30:07.690 |SdlStat |Period: 600s #Lines: 1 #Bytes: 252 Total Number of Buffers: 2000 Free LWM: 1998 Free LWM(total): 1934
00519767.000 |00:40:07.834 |SdlSig |AuditTimer |wait |Audit(1,600,19,1) |SdlTimerService(1,600,3,1) |1,600,26,1.1^*^* |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0]
00519768.000 |00:40:07.834 |SdlStat |Period: 600s #Lines: 1 #Bytes: 252 Total Number of Buffers: 2000 Free LWM: 1998 Free LWM(total): 1934
00519769.000 |00:40:09.089 |AppInfo |CTFTPDB_DeviceVersionRecords::loadRecords(), For DeviceId[a6b4a735-bdce-9e31-2564-2035accc5a8e] *** commondeviceconfig Record[] Not Found ***
00519770.000 |00:40:09.092 |AppInfo | TID[0962eb90] signTFTPFile(..) Signature Size:128
00519771.000 |00:46:53.574 |AppInfo |TID[9e514b90] TFTPEngine::CheckStaleRequests(),[0xd17b488~119~10.203.106.245~50784] Aborting after [1] Retries. Socket[16] Serving File[RingList.xml] Initial Packet#[1]
00519772.000 |00:46:53.574 |SdlStat |Period: 406s #Lines: 3 #Bytes: 482 Total Number of Buffers: 2000 Free LWM: 1998 Free LWM(total): 1934
00519773.000 |00:50:07.986 |SdlSig |AuditTimer |wait |Audit(1,600,19,1) |SdlTimerService(1,600,3,1) |1,600,26,1.1^*^* |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0]
00519774.000 |00:50:07.986 |SdlStat |Period: 194s #Lines: 1 #Bytes: 252 Total Number of Buffers: 2000 Free LWM: 1998 Free LWM(total): 1934
00519775.000 |00:51:40.865 |AppInfo |CTFTPDB_DeviceVersionRecords::loadRecords(), For DeviceId[57b65f4a-db19-d1fc-9f61-921089725f69] *** commondeviceconfig Record[] Not Found ***
00519776.000 |00:51:40.865 |SdlStat |Period: 93s #Lines: 1 #Bytes: 182 Total Number of Buffers: 2000 Free LWM: 1998 Free LWM(total): 1934
00519777.000 |00:51:40.867 |AppInfo | TID[0962eb90] signTFTPFile(..) Signature Size:128
00519778.000 |01:00:08.134 |SdlSig |AuditTimer |wait |Audit(1,600,19,1) |SdlTimerService(1,600,3,1) |1,600,26,1.1^*^* |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0]
00519779.000 |01:00:08.134 |SdlStat |Period: 508s #Lines: 2 #Bytes: 344 Total Number of Buffers: 2000 Free LWM: 1997 Free LWM(total): 1934
00519780.000 |01:10:08.286 |SdlSig |AuditTimer |wait |Audit(1,600,19,1) |SdlTimerService(1,600,3,1) |1,600,26,1.1^*^* |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0]
00519781.000 |01:10:08.286 |SdlStat |Period: 600s #Lines: 1 #Bytes: 252 Total Number of Buffers: 2000 Free LWM: 1998 Free LWM(total): 1934
00519782.000 |01:13:14.150 |AppInfo |CTFTPDB_DeviceVersionRecords::loadRecords(), For DeviceId[2479b68e-a722-5af5-c8e6-4701c388e94b] *** commondeviceconfig Record[] Not Found ***
00519783.000 |01:13:14.150 |SdlStat |Period: 186s #Lines: 1 #Bytes: 182 Total Number of Buffers: 2000 Free LWM: 1998 Free LWM(total): 1934
00519784.000 |01:13:14.152 |AppInfo | TID[0962eb90] signTFTPFile(..) Signature Size:128
00519785.000 |01:19:14.936 |AppInfo |CTFTPDB_DeviceVersionRecords::loadRecords(), For DeviceId[50f71831-1d34-570e-4221-d9871ed9ac21] *** commondeviceconfig Record[] Not Found ***
00519786.000 |01:19:14.936 |SdlStat |Period: 360s #Lines: 2 #Bytes: 274 Total Number of Buffers: 2000 Free LWM: 1997 Free LWM(total): 1934
00519787.000 |01:19:14.938 |AppInfo | TID[0962eb90] signTFTPFile(..) Signature Size:128
00519788.000 |01:20:08.426 |SdlSig |AuditTimer |wait |Audit(1,600,19,1) |SdlTimerService(1,600,3,1) |1,600,26,1.1^*^* |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0]
00519789.000 |01:20:08.426 |SdlStat |Period: 54s #Lines: 2 #Bytes: 344 Total Number of Buffers: 2000 Free LWM: 1997 Free LWM(total): 1934
00519790.000 |01:30:08.574 |SdlSig |AuditTimer |wait |Audit(1,600,19,1) |SdlTimerService(1,600,3,1) |1,600,26,1.1^*^* |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0]
00519791.000 |01:30:08.574 |SdlStat |Period: 600s #Lines: 1 #Bytes: 252 Total Number of Buffers: 2000 Free LWM: 1998 Free LWM(total): 1934
00519792.000 |01:39:20.779 |AppInfo |CTFTPDB_DeviceVersionRecords::loadRecords(), For DeviceId[77a19246-246f-40e3-0845-ec2aba0094e0] *** commondeviceconfig Record[] Not Found ***
00519793.000 |01:39:20.779 |SdlStat |Period: 552s #Lines: 1 #Bytes: 182 Total Number of Buffers: 2000 Free LWM: 1998 Free LWM(total): 1934
01-27-2014 11:18 PM
Hi Manish,
VGA224 might creating this issue as we are using this one, but in TFTP logs there is no such error regarding it. And the most strange thing is that I have pulled out TFTP logs of last three days and I counted total rows in logs and which are near about 3000 but in the same time stamp tftp aborted counter increased by near about 10000. Is there any other logs where we can find out something regarding this ?
Thanks,
Suresh
01-27-2014 11:22 PM
From the logs we can identify the Ip addresses that are being repeated the most and try to fix those first. I would also suggest a restart of the tftp and database layer monitor services if it has not been done yet.
HTH
Manish
01-27-2014 11:44 PM
Thanks a lot Manish for the suggestion, I have already planned to restart TFTP service on coming weekend, so along with that we will restart the Database Layer Monitor service as well, but 1 query do we need to restart Database Layer Monitor service service at all nodes (Pub & Subs) where Call manager and TFTP services are running ?
01-27-2014 11:45 PM
Yes.
Manish
02-09-2014 12:00 AM
Hi Manish,
I have restarted tftp and database layer monitor services on CUCM cluster but no difference. As you said some IP Phone, ATA or Vg224 creating this issue and that seems to be very true.
Actually I have enabled PCAP traces on CUCM and found one IP Phone, which was not registered to CUCM and even there was no entry of it's MAC there but I can browse that IP phone using its IP address and it showing correct callmanager and TFTP IP address there, In logs I've seen lots of registration failure error regarding this phone. Its strange how that phone showing all parameters correct and even auto registration is disabled on all nodes.Anyway i have removed that phone from the network.
I have two doubts here and one is, there was one ATA which was registered to CUCM and I just deleted it from CUCM but still getting below error message.
"A device attempted to register but did not complete registration Connecting Port:2000 Device Name:ATA......Device type:12 Reason Code:29 Protocol:SCCP...IPAddressAttributes:0 UNKNOWN_PARAMNAME:LastSignalReceived:DbStationAutoRegisterErr UNKNOWN_PARAMNAME:StationState:auto_register"
Another doubt is, for one VG224 gateway there are only 8 ports have been configured in CUCM due to license limitation but getting the same error for remaining ports which are not configured in CUCM and most strange thing is that we are getting same error for those VG224 ports which are registered to CUCM and working fine, below is error.
A device attempted to register but did not complete registration Connecting Port:2000 Device Name:ANDF0F9CF2E4414 Device IP Address:10.203.25.29 Device type:30027 Reason Code:3 Protocol:SCCP IPAddressAttributes:2 UNKNOWN_PARAMNAME:LastSignalReceived:StationRegister UNKNOWN_PARAMNAME:StationState:wait_register App
Could you please spare some time to put yours observation here...thanks in advance.
Regards, Suresh
02-09-2014 07:12 PM
Hi Suresh,
For ATA's and VG224's the ports which are not being used should be disabled otherwise you will keep on getting these registration requests. If you are getting such requests from ports that are configured fine then try bouncing sccp or mgcp on the vg224 ( depending on what is configured ) or try reconfiguring the port. In some cases i have seen customers use an ACL to block traffic from certain IP addresses coming towards cucm.
HTH
Manish
02-10-2014 04:01 AM
Thanks a lot Manish for your help, I will do the same and will see.
Regards,Suresh
Discover and save your favorite ideas. Come back to expert answers, step-by-step guides, recent topics, and more.
New here? Get started with these tips. How to use Community New member guide