02-24-2012 04:29 AM - edited 03-19-2019 04:28 AM
Need help investigating phones unregistering from Callmanager. The switchport and networking looks ok. It's seems sporadic.
CUCM Version 7.1.5
Phones Type 7975G (as far as I'm aware)
App Load ID jar75sccp.9-2-1TH1-13.sbn
Boot Load ID tnp75.8-3-4-16BN01.bin
Version SCCP75.9-2-1S
App Load ID jar75sccp.9-2-1TH1-13.sbn
Boot Load ID tnp75.8-3-4-16BN01.bin
Version SCCP75.9-2-1S
Phone log output
5274: WRN 17:31:34.522624 JVM: Startup Module Loader|cip.sccp.SccpEnhancedAlarmInfo:setLastDeregistrationReason - new reason=LastTimeFailback current=18,18,
5275: WRN 17:31:34.524284 JVM: Startup Module Loader|cip.sccp.cn:? - Read exception: java.io.EOFException
Close(d) Connection ..., errno=-1
5276: ERR 17:31:34.529554 JVM: 17:31:34|java.io.EOFException
at java.io.DataInputStream.readInt()I(Unknown Source)
at cip.io.i.readInt()I(Unknown Source)
at cip.sccp.ax.a()Lcip/sccp/bu;(Unknown Source)
at cip.sccp.cn.e()V(Unknown Source)
at cip.sys.l.run()V(Unknown Source)
at java.lang.Thread.startup(Z)V(Unknown Source)
5277: WRN 17:31:34.531736 JVM: Startup Module Loader|cip.sccp.SccpEnhancedAlarmInfo:propertyChanged - name=device.settings.fullyregistered value=false
5278: WRN 17:31:34.533345 JVM: Startup Module Loader|cip.sccp.SccpEnhancedAlarmInfo:propertyChanged - name=device.status.lastresetcause2 value=465
5279: WRN 17:31:34.534952 JVM: Startup Module Loader|cip.sccp.SccpEnhancedAlarmInfo:setLastDeregistrationReason - new reason=LastTimeTCPclosed current=18,18,18,
5280: WRN 17:31:34.536567 JVM: Startup Module Loader|cip.sccp.CcApi:? - alarm sending failure:14: Nome=SEPECC882B18A68 Load= SCCP75.9-2-1S Ultimo=UCM-closed-TCP
5281: WRN 17:31:34.595653 JVM: Startup Module Loader|cip.sccp.CcApi:? - CcAPI, LAST_RESET_CAUSE changed to 465
5282: WRN 17:31:34.598710 JVM: Startup Module Loader|cip.sccp.SccpEnhancedAlarmInfo:getLastUnregistrationTimeReason - TimeStamp=1330014593094,1330014643787,1330014694226,1330014694312; Reasons =18,18,18,14
5283: NOT 17:31:34.609007 JVM: Startup Module Loader|cip.midp.midletsuite.InstallerModule:? - propertyChanged - device.settings.fullyregistered value=false
5284: NOT 17:31:34.611429 JVM: Startup Module Loader|cip.midp.pushregistry.e:? - setAcceptConnections - DISABLED
5285: NOT 17:31:34.613003 JVM: Startup Module Loader|cip.cfg.ConfigManager:? - --->ConfigManager PropertyChanged: device.callagent.callcount
5286: NOT 17:31:34.614753 JVM: Startup Module Loader|cip.cfg.ConfigManager:? - <---ConfigManager PropertyChanged: device.callagent.callcount
5287: WRN 17:31:34.616348 CDP-D: lldpInetdStatsRsp: port: 0
5288: WRN 17:31:37.711267 JVM: Startup Module Loader|cip.sccp.SccpEnhancedAlarmInfo:setLastDeregistrationReason - new reason=LastTimeInitialized current=
5289: WRN 17:31:37.718226 JVM: Startup Module Loader|cip.sccp.SccpEnhancedAlarmInfo:propertyChanged - name=device.settings.fullyregistered value=false
5290: WRN 17:31:37.720118 JVM: Startup Module Loader|cip.sccp.SccpEnhancedAlarmInfo:propertyChanged - name=device.status.lastresetcause2 value=517
5291: WRN 17:31:37.729079 JVM: Startup Module Loader|cip.sccp.SccpEnhancedAlarmInfo:propertyChanged - name=device.settings.fullyregistered value=true
5292: WRN 17:31:37.731485 JVM: Startup Module Loader|cip.sccp.f:? - Unknown?? button in template. Button=48 inst=2
5293: WRN 17:31:37.733071 JVM: Startup Module Loader|cip.sccp.f:? - Unknown?? button in template. Button=49 inst=3
5294: WRN 17:31:37.734670 JVM: Startup Module Loader|cip.sccp.f:? - Unknown?? button in template. Button=54 inst=4
5295: DBG 17:31:38.543404 cffs_journal_commit() change journal base 0x460000
5296: DBG 17:31:38.544667 cffs_journal_create() sec 39
5297: DBG 17:31:38.546276 cffs_journal_commit() new journal base 0x4e0000/hdr:4/data:5
5298: NOT 17:31:38.759872 JVM: Startup Module Loader|cip.midp.midletsuite.InstallerModule:? - propertyChanged - device.callagent.messages.0 value=0
5299: NOT 17:31:38.761737 JVM: Startup Module Loader|cip.midp.midletsuite.InstallerModule:? - propertyChanged - device.callagent.messages.0 value=1
5300: WRN 17:31:38.763345 JVM: Startup Module Loader|DisplayTask:? - Line 1 property added with dn 8824511
5301: WRN 17:31:38.764973 JVM: Startup Module Loader|cip.sccp.CcApi:? - CcAPI, LAST_RESET_CAUSE changed to 517
5302: NOT 17:31:38.801106 JVM: Startup Module Loader|cip.midp.midletsuite.InstallerModule:? - propertyChanged - device.settings.fullyregistered value=true
5303: NOT 17:31:38.802738 JVM: Startup Module Loader|cip.midp.midletsuite.InstallerModule:? - FULLY_REGISTERED - Resetting retry installer interval
5304: NOT 17:31:38.804347 JVM: Startup Module Loader|cip.midp.pushregistry.e:? - setAcceptConnections - ENABLED
5305: NOT 17:31:38.805961 JVM: Startup Module Loader|cip.midp.midletsuite.InstallerModule:? - propertyChanged - device.settings.fullyregistered value=true
5306: NOT 17:31:38.807574 JVM: Startup Module Loader|cip.midp.midletsuite.InstallerModule:? - FULLY_REGISTERED - Resetting retry installer interval
5307: NOT 17:31:38.809131 JVM: Startup Module Loader|cip.midp.pushregistry.e:? - setAcceptConnections - ENABLED
5308: NOT 17:31:38.811498 JVM: Startup Module Loader|cip.midp.midletsuite.InstallerModule:? - propertyChanged - device.callagent.messages.0 value=1
5309: NOT 17:31:38.813156 JVM: Startup Module Loader|cip.midp.midletsuite.InstallerModule:? - propertyChanged - device.callagent.messages.0 value=1
5310: NOT 17:31:38.814766 JVM: Startup Module Loader|cip.cfg.t:? - Requesting CONFIG file from TFTP Service(1)
5311: NOT 17:31:38.816340 JVM: Startup Module Loader|cip.cfg.ConfigManager:? - --->ConfigManager PropertyChanged: device.callagent.callcount
5312: NOT 17:31:38.817998 JVM: Startup Module Loader|cip.cfg.ConfigManager:? - <---ConfigManager PropertyChanged: device.callagent.callcount
5313: NOT 17:31:38.819598 JVM: Startup Module Loader|cip.cfg.ConfigManager:? - --->ConfigManager PropertyChanged: device.callagent.callcount
5314: NOT 17:31:38.906116 JVM: Startup Module Loader|cip.cfg.ConfigManager:? - <---ConfigManager PropertyChanged: device.callagent.callcount
5315: ERR 17:31:38.928407 JVM: tftpClient SEPECC882B18A68.cnf.xml /usr/ram/SEPECC882B18A68.cnf.xml 550001 1
5316: WRN 17:31:38.932451 JVM: Startup Module Loader|cip.mmgr.dt:? - [MediaMgrSM]: Unhandled Event, State = StateOnHook Event = EventServicesTxStop
5317: NOT 17:31:38.934838 tftpClient: tftp request rcv'd from /usr/tmp/tftp, srcFile = SEPECC882B18A68.cnf.xml, dstFile = /usr/ram/SEPECC882B18A68.cnf.xml max size = 550001
5318: DBG 17:31:38.938452 cffs_gc(): runing gc 2
5319: NOT 17:31:38.950842 tftpClient: auth server - tftpList[0] = ::ffff:151.95.36.109
5320: NOT 17:31:38.951491 tftpClient: look up server - 0
5321: WRN 17:31:38.953586 SECD: WARN:lookupCTL: ** no CTL, assume TFTP NONSECURE
5322: NOT 17:31:38.956483 tftpClient: secVal = 0xa
5323: NOT 17:31:38.957220 tftpClient: ::ffff:151.95.36.109 is a NONsecure server
5324: NOT 17:31:38.957757 tftpClient: look up server - 1
5325: WRN 17:31:38.959676 SECD: WARN:lookupCTL: ** no CTL, assume TFTP NONSECURE
5326: NOT 17:31:38.963125 tftpClient: secVal = 0xa
5327: NOT 17:31:38.963868 tftpClient: ::ffff:151.95.36.108 is a NONsecure server
5328: NOT 17:31:38.964486 tftpClient: temp retval = SRVR_NONSECURE, keep looking
5329: NOT 17:31:38.965049 tftpClient: temp retval = SRVR_NONSECURE, keep looking
5330: NOT 17:31:38.965611 tftpClient: retval = 10
5331: NOT 17:31:38.966183 tftpClient: Secure file requested
5332: NOT 17:31:38.966738 tftpClient: Non secure file approved -- SEPECC882B18A68.cnf.xml
5333: DBG 17:31:39.604444 cffs_gc(): runing gc 1
5334: NOT 17:31:39.620371 TFTP: [19]:Requesting SEPECC882B18A68.cnf.xml from 151.95.36.109 with size limit of 550001
5335: NOT 17:31:39.635532 TFTP: [19]:Finished --> rcvd 7815 bytes
5336: WRN 17:31:39.645303 SECD: WARN:lookupCTL: ** no CTL, assume TFTP NONSECURE
5337: NOT 17:31:39.658251 JVM: Startup Module Loader|cip.cfg.t:? - Config handleTftpResponse, status=0 for file=ram/SEPECC882B18A68.cnf.xml
5338: ERR 17:31:40.274014 JVM: TVS server is : IPv4 : , IPv6 : , Port : 0, IPv4 : , IPv6 : , Port : 0, IPv4 : , IPv6 : , Port : 0, IP Mode : 0, IP Preference Mode: 0
5339: NOT 17:31:40.276298 SECD: handleTvsSetReq: IPv6 : , IPv6 : , IPv6 : , IP Mode : 0, IP Pref : 0 DSCP : 96
5340: WRN 17:31:40.280874 JVM: Startup Module Loader|cip.xml.ap:parse - Encoding Updated to UTF-8
5341: WRN 17:31:40.282471 JVM: Startup Module Loader|cip.xml.ap: - XML Parser Warning: Unknown element 'name' in element '/device/devicePool' (line=16)
5342: WRN 17:31:40.284042 JVM: Startup Module Loader|cip.xml.ap: - XML Parser Warning: Unknown element 'name' in element '/device/devicePool/dateTimeSetting' (line=18)
5343: WRN 17:31:40.285685 JVM: Startup Module Loader|cip.xml.ap: - XML Parser Warning: Unknown element 'name' in element '/device/devicePool/callManagerGroup' (line=30)
5344: WRN 17:31:40.287385 JVM: Startup Module Loader|cip.xml.ap: - XML Parser Warning: Unknown element 'tftpDefault' in element '/device/devicePool/callManagerGroup' (line=31)
5345: WRN 17:31:40.289048 JVM: Startup Module Loader|cip.xml.ap: - XML Parser Warning: Unknown element 'mgcpPorts' in element '/device/devicePool/callManagerGroup/members/member/callManager/ports' (line=41)
5346: WRN 17:31:40.295345 JVM: Startup Module Loader|cip.xml.ap: - XML Parser Warning: Unknown element 'mgcpPorts' in element '/device/devicePool/callManagerGroup/members/member/callManager/ports' (line=57)
5347: WRN 17:31:40.297018 JVM: Startup Module Loader|cip.xml.ap: - XML Parser Warning: Unknown element 'name' in element '/device/devicePool/srstInfo' (line=68)
5348: WRN 17:31:40.298584 JVM: Startup Module Loader|cip.xml.ap: - XML Parser Warning: Unknown element 'userModifiable' in element '/device/devicePool/srstInfo' (line=70)
5349: WRN 17:31:40.300557 JVM: Startup Module Loader|cip.xml.ap: - XML Parser Warning: Unknown element 'mlppDomainId' in element '/device/devicePool' (line=85)
5350: WRN 17:31:40.302161 JVM: Startup Module Loader|cip.xml.ap: - XML Parser Warning: Unknown element 'mlppIndicationStatus' in element '/device/devicePool' (line=86)
5351: WRN 17:31:40.303777 JVM: Startup Module Loader|cip.xml.ap: - XML Parser Warning: Unknown element 'preemption' in element '/device/devicePool' (line=87)
5352: WRN 17:31:40.305436 JVM: Startup Module Loader|cip.xml.ap: - XML Parser Warning: Unknown element 'ciscoCamera' in element '/device/enterpriseConfig' (line=102)
5353: WRN 17:31:40.307071 JVM: Startup Module Loader|cip.xml.ap: - XML Parser Warning: Unknown element 'uid' in element '/device/networkLocaleInfo' (line=114)
5354: WRN 17:31:40.308678 JVM: Startup Module Loader|cip.xml.ap: - XML Parser Warning: Unknown element 'mobility' in element '/device' (line=148)
5355: ERR 17:31:40.311879 JVM: Startup Module Loader|cip.cfg.t:? - DirectoryUrl http://151.95.36.7:8585/CiscoIPServices/CCIP/multidirectory2.aspsecuredirectoryUrl
5356: NOT 17:31:40.316553 JVM: Startup Module Loader|cip.cfg.t:? - setConfigTvsProperty IP mode 0IP Pref 0DSCP 96
5357: NOT 17:31:40.318189 JVM: Startup Module Loader|cip.sec.TvsProperty:? - TVS IPv4 - 1 :TVS IPv6 - 1 :TVS Port - 1:0TVS IPv4 - 2 :TVS IPv6 - 2 :TVS Port - 2:0TVS IPv4 - 3 :TVS IPv6 - 3 :TVS Port - 3:0IP Address Mode:0IP Preference Mode:0
5358: NOT 17:31:41.435801 SECD: loadTvsSrvrCfg: Not in EMCC mode.Loading the flash file :/flash0/sec/misc/tvs.conf
5359: NOT 17:31:41.450591 JVM: emccMode=0,localOverride=0, tftpAddr1=, tftpAddr2=,tftpAddr3=,tftpAddr4=
5360: NOT 17:31:41.455339 tftpClient: tftp request rcv'd from /usr/tmp/tftp, emccMode =0, emccLocalOverride=0, tempTftp1= , tempTftp2 = , tempTftp3 = , tempTftp4 =
5361: NOT 17:31:41.456710 JVM: setTempTftpAddress, emcc_mode=0,retEmccMode=0,LocalOverride=0,retLocalOverride=0, status=1
5362: NOT 17:31:41.465607 SECD: clearTFTPList: cleared all TFTP entries
5363: ERR 17:31:41.529262 JVM: Startup Module Loader|cip.mmgr.MediaManager:? -
MediaManager propertyChanged called device.settings.config.ipaddressingmode
5364: ERR 17:31:41.954382 JVM: Startup Module Loader|cip.cfg.t:? - Delete of sshUserInfo file failed
5365: ERR 17:31:41.955986 JVM: Startup Module Loader|cip.cfg.t:? - informationUrl is http://151.95.36.101:8080/ccmcip/GetTelecasterHelpText.jsp
5366: ERR 17:31:41.957589 JVM: Startup Module Loader|cip.cfg.t:? - directoriesUrl is http://151.95.36.7:8585/CiscoIPServices/CCIP/multidirectory2.asp
5367: ERR 17:31:41.959215 JVM: Startup Module Loader|cip.cfg.t:? - messagesUrl is
5368: ERR 17:31:41.962558 JVM: Calling enable listening for incoming http connections
5369: ERR 17:31:41.965352 JVM: Startup Module Loader|cip.cfg.t:? - servicesUrl is http://151.95.36.7:8585/CiscoIPServices/CCIP/ibm_ge_menu2.xml
5370: ERR 17:31:41.966940 JVM: Startup Module Loader|cip.cfg.t:? - authenticationUrl is http://151.95.36.101:8080/ccmcip/authenticate.jsp
5371: ERR 17:31:41.968567 JVM: Startup Module Loader|cip.cfg.t:? - idleUrl is 0
5372: ERR 17:31:41.970144 JVM: Startup Module Loader|cip.cfg.t:? - messagesUrl is null
5373: ERR 17:31:41.971758 JVM: Startup Module Loader|cip.cfg.t:? - After set servicesUrl device.settings.config.servicesurl value http://151.95.36.7:8585/CiscoIPServices/CCIP/ibm_ge_menu2.xml
5374: ERR 17:31:41.973382 JVM: Startup Module Loader|cip.cfg.t:? - After set info url device.settings.config.informationurl value http://151.95.36.101:8080/ccmcip/GetTelecasterHelpText.jsp
5375: ERR 17:31:41.975025 JVM: Startup Module Loader|cip.cfg.t:? - After set dir Url device.settings.config.directoriesurl value http://151.95.36.7:8585/CiscoIPServices/CCIP/multidirectory2.asp
5376: ERR 17:31:41.976610 JVM: Startup Module Loader|cip.cfg.t:? - After set idle Url device.settings.config.idleurl value 0
5377: ERR 17:31:41.978217 JVM: Startup Module Loader|cip.cfg.t:? - After set sec auth Url device.settings.config.authenticationurl value http://151.95.36.101:8080/ccmcip/authenticate.jsp
5378: xxx 17:31:41.982627 JVM: Calling enable listening for incoming http connections
5379: ERR 17:31:41.979889 JVM: Startup Module Loader|VendorConfig:? - vendorconfig : setConfigProperties
5380: ERR 17:31:41.985975 JVM: Startup Module Loader|VendorConfig:? -
About to set WebAccess
5381: WRN 17:31:41.987534 JVM: Startup Module Loader|DisplayTask:? - resetCurrentPowerState(): Energywise is disabled
5382: WRN 17:31:41.989081 JVM: Startup Module Loader|DisplayTask:? - resetCurrentPowerState(): Energywise null domain
5383: WRN 17:31:41.990815 JVM: Startup Module Loader|DisplayTask:? - resetCurrentPowerState(): Energywise null secret
5384: WRN 17:31:41.992403 JVM: Startup Module Loader|DisplayTask:? - resetCurrentPowerState(): no time changed, so needn't reschedule existing timer
5385: ERR 17:31:41.994800 JVM: Startup Module Loader|VendorConfig:? - WebAccess true
5386: ERR 17:31:41.996359 JVM: Startup Module Loader|VendorConfig:? - WebProtocol 0
5387: NOT 17:31:41.997947 JVM: Startup Module Loader|VendorConfig:? - Setting 80-bit-srtp to false
5388: ERR 17:31:41.999535 JVM: Startup Module Loader|cip.mmgr.MediaManager:? -
MediaManager propertyChanged called device.settings.config.vendorconfig.sidetonelevel
5389: NOT 17:31:42.004383 JVM: Startup Module Loader|VendorConfig:? - Setting RTCP to false
5390: NOT 17:31:42.006148 JVM: Startup Module Loader|cip.midp.midletsuite.InstallerModule:? - propertyChanged - device.settings.config.localization.userlocale.charset value=iso-8859-1
5391: NOT 17:31:42.007818 JVM: Startup Module Loader|cip.midp.midletsuite.InstallerModule:? - propertyChanged - device.settings.config.localization.userlocale.languagecode value=it_IT
5392: NOT 17:31:42.013914 SECD: setSecMode: sec mode set to NONE (was NONE)
5393: ERR 17:31:42.021999 JVM: Calling enable listening for incoming http connections
5394: NOT 17:31:42.738730 JVM: Startup Module Loader|cip.midp.midletsuite.InstallerModule:? - propertyChanged - device.settings.config.phoneservices value=cip.props.XmlProperty@828ae2
5395: NOT 17:31:42.740932 INETD: Set IP mode 1
5396: NOT 17:31:42.741567 INETD: Requestted IP mode is same as current mode
5397: NOT 17:31:42.742402 INETD: inetdSetSSHAccess: 0 -> 0
5398: NOT 17:31:42.743005 INETD: sshAccessWriteConf: old sshAccess:0, new sshAccess:0
5399: DBG 17:31:42.757463 VPNU: SM wakeup - chld=0 tmr=0 io=1 res=0
5400: DBG 17:31:42.771994 VPNU: No VPN database change
5401: NOT 17:31:42.776023 SECD: clearSRSTList: cleared all SRST entries
5402: WRN 17:31:42.933241 SECD: WARN:cancelCapfOp: CAPF not in use, user cancel ignored
5403: NOT 17:31:42.933955 SECD: clearCapfList: CAPF table cleared
07-25-2012 04:11 PM
I am seeing similar issues for a customer and was curious if you ever got a resolution to this issue.
Sent from Cisco Technical Support iPad App
07-31-2012 10:58 AM
I'm seeing something similiar was well. Did you ever open a TAC case to get a response?
09-26-2013 07:51 AM
Check the Maximum number of Registered Devices setting in your services parmitor. Default is 5000.
This parameter specifies the maximum number of devices that can register with Cisco CallManager and is used to limit the overall resource demand. Devices that count toward this limit include: Annunciator devices, H.323 gatekeepers, H.323 phones, H.323 gateways, ICT trunks (gatekeeper or non-gatekeeper-controlled), MGCP CAS trunks, MGCP gateways, MGCP FXS ports (analog ports), MGCP FXO ports, MGCP T1/E1 PRI, media termination points (hardware or software), transcoders, Music on Hold servers (not MOH audio sources), SIP trunks, IP phones, conference bridge devices (hardware or software), legacy Skinny Gateway Control Protocol devices like Cisco Analog Access, and video conference bridges (IP/VC 3540 configured with Skinny Client Control Protocol [SCCP] port). The following devices are NOT counted toward this limit: line appearances (directory numbers), route lists, Remote Destinations and built in bridges.
Note: CTI Route Points and ports are not listed but do count.
11-12-2013 05:24 PM
Hi John,
I am wondering two things based on your post. Is there a way to determine if the number of registered devices is close or exceeding this parameter? Do you believe that being close to the maimum or exceeding the maximum is causing the disconnect?
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