7975G IP Phones Unregister from CUCM

[Tracey Campbell]

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

[joel.davila]

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

[aod]

I'm seeing something similiar was well.  Did you ever open a TAC case to get a response? 

[john.jacobs]

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. 

[pingaunis]

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?