09-11-2013 12:56 PM - edited 03-16-2019 07:19 PM
I have a 7962 phone that is working on CUCM 8,5 as soon as i tried to force it to register with GW it fails. I know it could be several things on the network however looking at Status messages and console logs from phone web page it appears that it is related to ITL/CTL files on the phone but not sure. Can someone look at attached logs and through some light on it. Any assistance would be appreciated. The GW is 3845 and is running SRST 8.6.
Thanks in advance
5035: NOT 15:42:53.523808 JVM: Startup Module Loader|cip.sccp.CcApi: - cfgRetryTimer: will try to sync up the configuration..
5036: NOT 15:42:53.525201 JVM: Startup Module Loader|cip.sccp.CcApi: - handleCfgRetryTimer(): tftp server is not up, request default file to check
5037: ERR 15:42:53.528659 JVM: tftpClient XMLDefault.cnf.xml /usr/cache/TFTP-533107284 550001 1
5038: NOT 15:42:53.532252 tftpClient: tftp request rcv'd from /usr/tmp/tftp, srcFile = XMLDefault.cnf.xml, dstFile = /usr/cache/TFTP-533107284 max size = 550001
5039: NOT 15:42:53.551346 tftpClient: auth server - tftpList[0] = ::ffff:192.168.182.165
5040: NOT 15:42:53.551917 tftpClient: look up server - 0
5041: NOT 15:42:53.553614 SECD: lookupCTL: TFTP SRVR secure
5042: NOT 15:42:53.556097 tftpClient: secVal = 0x9
5043: NOT 15:42:53.556744 tftpClient: ::ffff:192.168.182.165 is a secure server
5044: NOT 15:42:53.557237 tftpClient: look up server - 1
5045: NOT 15:42:53.558925 SECD: lookupCTL: TFTP SRVR secure
5046: NOT 15:42:53.561317 tftpClient: secVal = 0x9
5047: NOT 15:42:53.561966 tftpClient: ::ffff:192.168.182.165 is a secure server
5048: NOT 15:42:53.562470 tftpClient: retval = SRVR_SECURE
5049: NOT 15:42:53.562937 tftpClient: Secure file requested
5050: NOT 15:42:53.563451 tftpClient: authenticated file approved - add .sgn -- XMLDefault.cnf.xml.sgn
5051: NOT 15:42:53.571719 JVM: Startup Module Loader|cip.sccp.CcApi: - handlecfgRetryTimer(): tftp server is up, update ctl/itl file
5052: NOT 15:42:53.577434 SECD: loadTvsSrvrCfg: Not in EMCC mode.Loading the flash file :/flash0/sec/misc/tvs.conf
5053: NOT 15:42:53.586377 JVM: emccMode=0,localOverride=0, tftpAddr1=, tftpAddr2=,tftpAddr3=,tftpAddr4=
5054: NOT 15:42:53.589206 tftpClient: tftp request rcv'd from /usr/tmp/tftp, emccMode =0, emccLocalOverride=0, tempTftp1= , tempTftp2 = , tempTftp3 = , tempTftp4 =
5055: NOT 15:42:53.591127 JVM: setTempTftpAddress, emcc_mode=0,retEmccMode=0,LocalOverride=0,retLocalOverride=0, status=1
5056: NOT 15:42:53.595562 JVM: Startup Module Loader|cip.cfg.ConfigManager:? - Starting CTL/config file updating
5057: NOT 15:42:53.661458 SECD: updateCTL: starting Trust list update
5058: NOT 15:42:53.663939 SECD: tlRequestFile: Socket 9 connected to /usr/tmp/tftpClientSock
5059: NOT 15:42:53.664811 SECD: tlRequestFile: Request CTLSEPB8621F6D9981.tlv
5060: NOT 15:42:53.668246 tftpClient: tftp request rcv'd from /usr/tmp/ctlSock, srcFile = CTLSEPB8621F6D9981.tlv, dstFile = /usr/tmp/CTLFile.tlv
5061: NOT 15:42:53.680791 tftpClient: auth server - tftpList[0] = ::ffff:192.168.182.165
5062: NOT 15:42:53.681348 tftpClient: look up server - 0
5063: NOT 15:42:53.683064 SECD: lookupCTL: TFTP SRVR secure
5064: NOT 15:42:53.685415 tftpClient: secVal = 0x9
5065: NOT 15:42:53.686102 tftpClient: ::ffff:192.168.182.165 is a secure server
5066: NOT 15:42:53.686604 tftpClient: look up server - 1
5067: NOT 15:42:53.688308 SECD: lookupCTL: TFTP SRVR secure
5068: NOT 15:42:53.691248 tftpClient: secVal = 0x9
5069: NOT 15:42:53.691897 tftpClient: ::ffff:192.168.182.165 is a secure server
5070: NOT 15:42:53.692397 tftpClient: retval = SRVR_SECURE
5071: NOT 15:42:53.692864 tftpClient: Non secure file requested
5072: NOT 15:42:53.730861 TFTP: [9]:Requesting CTLSEPB8621F6D9981.tlv from 192.168.182.165
5073: WRN 15:42:53.732760 TFTP: [9]:recvfrom error : Connection refused .
5074: NOT 15:42:53.741156 SYSMSG: pid 9 (/sbin/tftpd) Normal Exit, status = 25
5075: INF 15:42:53.741192 runtime = 0.040 secs
5076: INF 15:42:53.741212 user cpu = 0.001298530 secs
5077: INF 15:42:53.741230 system cpu = 0.010138940 secs
5078: INF 15:42:53.741244 child user cpu = 0.000000000 secs
5079: INF 15:42:53.741258 child sys cpu = 0.000000000 secs
5080: INF 15:42:53.741278 sys interrupts = 0.001283360 secs for 29 interrupts
5081: INF 15:42:53.741300 total cpu = 0.011437470 secs ( 25% utilization )
5082: NOT 15:42:53.770938 TFTP: [20]:Requesting CTLSEPB8621F6D9981.tlv from 192.168.182.165
5083: ERR 15:42:57.554340 JVM: WcAnalyzeUrl: Port = 8443, scheme = eWcSchemeHttp, fHostName =
5084: ERR 15:42:57.555735 JVM: WcAnalyzeUrl: Port = 8443, scheme = eWcSchemeHttp, fHostName =
5085: ERR 15:42:57.556313 JVM: _HTTPMakeRequest1: Processing Non-HTTPS URL, URL : http://172.30.198.39:8443/ccmcip/authenticate.jsp?UserID=uplinx_remote_user&Password=r3m0t3_us3r&devicename=SEPB8621F6D9981
5086: ERR 15:42:57.556911 JVM: Not TLS <0> or Not DefaultTls Port <8443>
5087: ERR 15:42:57.558317 JVM: httpFSM: Calling StcpActiveConnectionStatus, result 0
5088: ERR 15:42:57.558954 JVM: httpFSM: Calling StcpActiveConnectionStatus, result 0
5089: ERR 15:42:57.559522 JVM: httpFSM: Calling StcpActiveConnectionStatus, result 0
5090: ERR 15:42:57.560384 JVM: httpFSM: Calling StcpActiveConnectionStatus, result 0
5091: ERR 15:42:57.580409 JVM: httpFSM: Calling StcpActiveConnectionStatus, result 0
5092: ERR 15:42:57.581031 JVM: httpFSM: Calling StcpActiveConnectionStatus, result 0
5093: ERR 15:42:57.581606 JVM: httpFSM: Calling StcpActiveConnectionStatus, result 0
5094: ERR 15:42:57.582180 JVM: httpFSM: Calling StcpActiveConnectionStatus, result 0
5095: ERR 15:42:57.582740 JVM: httpFSM: Calling StcpActiveConnectionStatus, result 0
5096: ERR 15:42:57.583317 JVM: httpFSM: Calling StcpActiveConnectionStatus, result 0
5097: ERR 15:42:57.600470 JVM: httpFSM: Calling StcpActiveConnectionStatus, result 0
5098: ERR 15:42:57.640446 JVM: httpFSM: Calling StcpActiveConnectionStatus, result 0
5099: ERR 15:42:57.700479 JVM: httpFSM: Calling StcpActiveConnectionStatus, result 0
5100: NOT 15:42:57.863147 TFTP: [20]:Timeout --> retransmit the last packet
5101: WRN 15:42:57.863956 TFTP: [20]:recvfrom error : Connection refused .
5102: NOT 15:42:57.872000 SYSMSG: pid 20 (/sbin/tftpd) Normal Exit, status = 25
5103: INF 15:42:57.872036 runtime = 4.120 secs
5104: INF 15:42:57.872056 user cpu = 0.001338460 secs
5105: INF 15:42:57.872075 system cpu = 0.014563390 secs
5106: INF 15:42:57.872088 child user cpu = 0.000000000 secs
5107: INF 15:42:57.872103 child sys cpu = 0.000000000 secs
5108: INF 15:42:57.872124 sys interrupts = 0.039726610 secs for 776 interrupts
5109: INF 15:42:57.872146 total cpu = 0.015901850 secs ( 0% utilization )
5110: ERR 15:42:58.300653 JVM: WcAnalyzeUrl: Port = 8443, scheme = eWcSchemeHttp, fHostName =
5111: ERR 15:42:58.302055 JVM: WcAnalyzeUrl: Port = 8443, scheme = eWcSchemeHttp, fHostName =
5112: ERR 15:42:58.302637 JVM: _HTTPMakeRequest1: Processing Non-HTTPS URL, URL : http://172.30.198.39:8443/ccmcip/authenticate.jsp?UserID=uplinx_remote_user&Password=r3m0t3_us3r&devicename=SEPB8621F6D9981
5113: ERR 15:42:58.303187 JVM: Not TLS <0> or Not DefaultTls Port <8443>
5114: ERR 15:42:58.304607 JVM: httpFSM: Calling StcpActiveConnectionStatus, result 0
5115: ERR 15:42:58.305277 JVM: httpFSM: Calling StcpActiveConnectionStatus, result 0
5116: ERR 15:42:58.305850 JVM: httpFSM: Calling StcpActiveConnectionStatus, result 0
5117: ERR 15:42:58.306423 JVM: httpFSM: Calling StcpActiveConnectionStatus, result 0
5118: ERR 15:42:58.320450 JVM: httpFSM: Calling StcpActiveConnectionStatus, result 0
5119: ERR 15:42:58.360432 JVM: httpFSM: Calling StcpActiveConnectionStatus, result 0
5120: ERR 15:42:58.423810 JVM: httpFSM: Calling StcpActiveConnectionStatus, result 0
5121: NOT 15:43:01.871194 SECD: tlRequestFile: tftp Status 25 rcv'd
5122: NOT 15:43:01.872017 SECD: updateCTL: finished CTLFile update
5123: NOT 15:43:01.874347 SECD: tlRequestFile: Socket 9 connected to /usr/tmp/tftpClientSock
5124: NOT 15:43:01.875160 SECD: tlRequestFile: Request ITLSEPB8621F6D9981.tlv
5125: NOT 15:43:01.875896 tftpClient: tftp request rcv'd from /usr/tmp/ctlSock, srcFile = ITLSEPB8621F6D9981.tlv, dstFile = /usr/tmp/ITLFile.tlv
5126: NOT 15:43:01.890705 tftpClient: auth server - tftpList[0] = ::ffff:192.168.182.165
5127: NOT 15:43:01.891305 tftpClient: look up server - 0
5128: NOT 15:43:01.893080 SECD: lookupCTL: TFTP SRVR secure
5129: NOT 15:43:01.895442 tftpClient: secVal = 0x9
5130: NOT 15:43:01.896117 tftpClient: ::ffff:192.168.182.165 is a secure server
5131: NOT 15:43:01.896618 tftpClient: look up server - 1
5132: NOT 15:43:01.898350 SECD: lookupCTL: TFTP SRVR secure
5133: NOT 15:43:01.901348 tftpClient: secVal = 0x9
5134: NOT 15:43:01.902029 tftpClient: ::ffff:192.168.182.165 is a secure server
5135: NOT 15:43:01.902572 tftpClient: retval = SRVR_SECURE
5136: NOT 15:43:01.903089 tftpClient: Non secure file requested
5137: NOT 15:43:01.904190 SECD: tlRequestFile: tftp Status 5 rcv'd
5138: NOT 15:43:01.905006 SECD: updateCTL: finished ITLFile update
5139: ERR 15:43:01.905624 SECD: EROR:updateCTL: ** Trust list update failed (have old TList)
5140: ERR 15:43:01.988049 JVM: Startup Module Loader|cip.sec.t:---------updateCtl,result=10 - -------------invoke proxy
5141: ERR 15:43:01.998403 JVM: Startup Module Loader|cip.sec.t:---------updateCtl,result=10 - -------------invoke dispatcher
5142: NOT 15:43:01.999825 JVM: Startup Module Loader|cip.cfg.k:? - ConfigManager updateCTL() rc=10 retryCount=0
5143: WRN 15:43:02.004066 SECD: WARN:getTLInfoFromFile: ** phone has no TL file /flash0/sec/ctl//CTLFile.tlv
5144: NOT 15:43:02.008266 SECD: parseHdr(): start of pad ('T' 0x0d) at TLV 15
5145: NOT 15:43:02.008862 SECD: parseHdr(): hdr ver 1.2 (knows upto 2.0)
5146: NOT 15:43:02.009395 SECD: parseHdr(): skipping 3 trail bytes (pad and/or unknown TLVs)
5147: WRN 15:43:02.010113 SECD: WARN:getTLInfoFromFile: TL signer's issuer name too big, may truncate
5148: NOT 15:43:02.059388 JVM: Startup Module Loader|cip.cfg.t:? - Requesting CONFIG file from TFTP Service(1)
5149: ERR 15:43:02.063406 JVM: tftpClient SEPB8621F6D9981.cnf.xml /usr/ram/SEPB8621F6D9981.cnf.xml 550001 1
5150: NOT 15:43:02.066244 tftpClient: tftp request rcv'd from /usr/tmp/tftp, srcFile = SEPB8621F6D9981.cnf.xml, dstFile = /usr/ram/SEPB8621F6D9981.cnf.xml max size = 550001
5151: NOT 15:43:02.085665 tftpClient: auth server - tftpList[0] = ::ffff:192.168.182.165
09-11-2013 02:05 PM
What is the IP address of the SRST reference? Is 192.168.182.165 your CUCM? Do you have the phone assigned to a device pool which has the correct SRST reference?
Please rate useful posts.
09-11-2013 02:16 PM
192.168.182.165 is SRST Gw... I have this manually set as tftp address on phone. It didn't worked throught dhcp do I tried to assign this manually
Btw phone web shows 182.165 as cm3..
Sent from Cisco Technical Support iPhone App
09-11-2013 02:20 PM
As far as I know you cannot set the TFTP address manually for SRST. You will have to specify it in the SRST reference under the Device pool. The SRST reference is not pushed down using DHCP but through the device pool directly from UCM.
What do you have for SRST configuration on the gateway?
Please rate useful posts.
09-11-2013 03:11 PM
Thats correct. The phone will have a third or standby call manager in the unified configuration on the phones settings menu which is set in your device pool and srst reference setting from the cucm system menu. This tells the phone to rehome to the srst router only when the phone was actively registered to a cucm and then loses connection.
Sent from Cisco Technical Support iPhone App
09-11-2013 03:22 PM
I understand the concept however all I am trying to test is register a phone that is on cucm 8.5 and register to SRST Gw that has telephony service on.
Sent from Cisco Technical Support iPhone App
09-11-2013 03:30 PM
Create an access list that will block port 2000 from the phone to the cucm and the phone will try to reg to the srst router
Sent from Cisco Technical Support iPhone App
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