CCM Service + Event Viewer

Andreas Wittemann · ‎09-02-2015

Hi community,

we experience sort of a strange problem here, but only with our 6945 IP-phones...the telephony part reboots suddenly, several times a day.
Users can see it on their displays, even calls get interrupted due to this. When checking more detailed we could see that the error-log on the phones themselves shows:

Name=SEP00077xxxxxx Load=SCCP6945.9-4-1-3 Last=CM-reset-TCP

The connection itself was stable, no interruptions between the branch where these phones reside towards our HQ with the two callmanagers.
I also applied QoS on the two tunnels branch towards our HQ. and checked the policies...nothing obviously wrong there.

I even updated everything yesterday, including CUCM to 10.5.2.1.12901-1 (latest for 10.5) as well as phone firmware to SCCP 9-4-1-3, latest one available for these phones...to do the first steps.

Nothing changed, we still have these resets. As said, none of the other phones there is affected of this problem, only the 6945 ones...which sorrily are the ones being used mainly there, so quite a lot of users are affected.
I didn´t see anything obvious around on the net, regarding this message of the phones...only that the reset seems to be initiated by the CM.

See below some error messages i found with RTMT for one of these affected devices, just as example. Was from /syslog/AlternateSyslog

Any ideas on this?

Thank you in advance,
Andreas

Sep 01 20:28:23 callmanager1 local7 6 : 179: callmanager1.sg.local Sep 01 2015 18:28:23 UTC : %UC_-6-LastOutOfServiceInformation: %[DeviceName=SEP00077dxxxxxx][DeviceIPv4Address=192.168.10.123/23][IPv4DefaultGateway=192.168.10.1][DeviceIPv6Address=][IPv6DefaultGateway=][ModelNumber=CP-6945][NeighborIPv6Address=][NeighborIPv4Address=192.168.111.7][NeighborDeviceID=SWITCH2][NeighborPortID=GigabitEthernet1/0/14][DHCPv4Status=1][DHCPv6Status=1][TFTPCfgStatus=1][DNSStatusUnifiedCM1=1][DNSStatusUnifiedCM2=1][VoiceVLAN=10][UnifiedCMIPAddress=192.168.20.20][LocalPort=50568][TimeStamp=1441132102][ReasonForOutOfService=100][LastProtocolEventSent=0x27][LastProtocolEventReceived=0x100][AppID=Cisco CallManager][ClusterID=StandAloneCluster][NodeID=callmanager1]: Information related to the last out-of-service event

Sep 01 20:28:23 callmanager1 local7 6 : 180: callmanager1.sg.local Sep 01 2015 18:28:23 UTC : %UC_CALLMANAGER-6-EndPointRegistered: %[DeviceName=SEP00077Dxxxxxx][IPAddress=192.168.10.123][Protocol=SCCP][DeviceType=564][PerfMonObjType=2][Description=TESTPHONE 6945][UserID=testuser][LoadID=SCCP6945.9-4-1-3][AssociatedDNs=7777,7700][MACAddress=00077Dxxxxxx][IPAddrAttributes=3][ActiveLoadId=SCCP6945.9-4-1-3][AppID=Cisco CallManager][ClusterID=StandAloneCluster][NodeID=callmanager1]: Endpoint registered

Sep 01 20:28:23 callmanager1 local7 6 : 181: callmanager1.sg.local Sep 01 2015 18:28:23 UTC : %UC_CALLMANAGER-6-DeviceDnInformation: %[DeviceName=SEP00077Dxxxxxx][DeviceType=564][StationDesc=TESTPHONE 6945][StationDn=7777, 7700,][AppID=Cisco CallManager][ClusterID=StandAloneCluster][NodeID=callmanager1]: List of directory numbers (DN) associated with this device

Sep 02 06:54:38 callmanager1 local7 6 : 2480: callmanager1.sg.local Sep 02 2015 04:54:38 UTC : %UC_CALLMANAGER-6-StationConnectionError: %[DeviceName=SEP00077Dxxxxxx][ReasonCode=2][AppID=Cisco CallManager][ClusterID=StandAloneCluster][NodeID=callmanager1]: Station device is closing the connection

Sep 02 06:54:38 callmanager1 local7 3 : 2481: callmanager1.sg.local Sep 02 2015 04:54:38 UTC : %UC_CALLMANAGER-3-EndPointUnregistered: %[DeviceName=SEP00077Dxxxxxx][IPAddress=192.168.10.123][Protocol=SCCP][DeviceType=564][Description=TESTPHONE 6945][Reason=13][MACAddress=00077Dxxxxxx][IPAddrAttributes=3][AppID=Cisco CallManager][ClusterID=StandAloneCluster][NodeID=callmanager1]: An endpoint has unregistered

Sep 02 06:54:40 callmanager1 local7 6 : 2503: callmanager1.sg.local Sep 02 2015 04:54:40 UTC : %UC_-6-LastOutOfServiceInformation: %[DeviceName=SEP00077dxxxxxx][DeviceIPv4Address=192.168.10.123/32][IPv4DefaultGateway=192.168.10.1][DeviceIPv6Address=][IPv6DefaultGateway=][ModelNumber=CP-6945][NeighborIPv6Address=][NeighborIPv4Address=192.168.111.7][NeighborDeviceID=SWITCH2][NeighborPortID=GigabitEthernet1/0/14][DHCPv4Status=1][DHCPv6Status=1][TFTPCfgStatus=1][DNSStatusUnifiedCM1=1][DNSStatusUnifiedCM2=1][VoiceVLAN=10][UnifiedCMIPAddress=192.168.20.20][LocalPort=51080][TimeStamp=1441169660][ReasonForOutOfService=14][LastProtocolEventSent=0x27][LastProtocolEventReceived=0x100][AppID=Cisco CallManager][ClusterID=StandAloneCluster][NodeID=callmanager1]: Information related to the last out-of-service event

Sep 02 06:54:41 callmanager1 local7 6 : 2537: callmanager1.sg.local Sep 02 2015 04:54:41 UTC : %UC_CALLMANAGER-6-EndPointRegistered: %[DeviceName=SEP00077Dxxxxxx][IPAddress=192.168.10.123][Protocol=SCCP][DeviceType=564][PerfMonObjType=2][Description=TESTPHONE 6945][UserID=testuser][LoadID=SCCP6945.9-4-1-3][AssociatedDNs=7777,7700][MACAddress=00077Dxxxxxx][IPAddrAttributes=3][ActiveLoadId=SCCP6945.9-4-1-3][AppID=Cisco CallManager][ClusterID=StandAloneCluster][NodeID=callmanager1]: Endpoint registered

Sep 02 06:54:41 callmanager1 local7 6 : 2538: callmanager1.sg.local Sep 02 2015 04:54:41 UTC : %UC_CALLMANAGER-6-DeviceDnInformation: %[DeviceName=SEP00077Dxxxxxx][DeviceType=564][StationDesc=TESTPHONE 6945][StationDn=7777, 7700,][AppID=Cisco CallManager][ClusterID=StandAloneCluster][NodeID=callmanager1]: List of directory numbers (DN) associated with this device

Sep 02 08:00:02 callmanager1 local7 6 : 2993: callmanager1.sg.local Sep 02 2015 06:00:02 UTC : %UC_-6-LastOutOfServiceInformation: %[DeviceName=SEP00077dxxxxxx][DeviceIPv4Address=192.168.10.123/32][IPv4DefaultGateway=192.168.10.1][DeviceIPv6Address=][IPv6DefaultGateway=][ModelNumber=CP-6945][NeighborIPv6Address=][NeighborIPv4Address=192.168.111.7][NeighborDeviceID=SWITCH2][NeighborPortID=GigabitEthernet1/0/14][DHCPv4Status=1][DHCPv6Status=1][TFTPCfgStatus=1][DNSStatusUnifiedCM1=1][DNSStatusUnifiedCM2=1][VoiceVLAN=10][UnifiedCMIPAddress=192.168.20.20][LocalPort=15241][TimeStamp=1441173596][ReasonForOutOfService=10][LastProtocolEventSent=0x27][LastProtocolEventReceived=0x100][AppID=Cisco CallManager][ClusterID=StandAloneCluster][NodeID=callmanager1]: Information related to the last out-of-service event

Sep 02 08:00:02 callmanager1 local7 6 : 2994: callmanager1.sg.local Sep 02 2015 06:00:02 UTC : %UC_CALLMANAGER-6-StationConnectionError: %[DeviceName=SEP00077Dxxxxxx][ReasonCode=4][AppID=Cisco CallManager][ClusterID=StandAloneCluster][NodeID=callmanager1]: Station device is closing the connection

Sep 02 08:00:02 callmanager1 local7 3 : 2995: callmanager1.sg.local Sep 02 2015 06:00:02 UTC : %UC_CALLMANAGER-3-EndPointUnregistered: %[DeviceName=SEP00077Dxxxxxx][IPAddress=192.168.10.123][Protocol=SCCP][DeviceType=564][Description=TESTPHONE 6945][Reason=16][MACAddress=00077Dxxxxxx][IPAddrAttributes=3][AppID=Cisco CallManager][ClusterID=StandAloneCluster][NodeID=callmanager1]: An endpoint has unregistered

Sep 02 08:00:02 callmanager1 local7 6 : 3004: callmanager1.sg.local Sep 02 2015 06:00:02 UTC : %UC_CALLMANAGER-6-EndPointRegistered: %[DeviceName=SEP00077Dxxxxxx][IPAddress=192.168.10.123][Protocol=SCCP][DeviceType=564][PerfMonObjType=2][Description=TESTPHONE 6945][UserID=testuser][LoadID=SCCP6945.9-4-1-3][AssociatedDNs=7777,7700][MACAddress=00077Dxxxxxx][IPAddrAttributes=3][ActiveLoadId=SCCP6945.9-4-1-3][AppID=Cisco CallManager][ClusterID=StandAloneCluster][NodeID=callmanager1]: Endpoint registered

Sep 02 08:00:02 callmanager1 local7 6 : 3005: callmanager1.sg.local Sep 02 2015 06:00:02 UTC : %UC_CALLMANAGER-6-DeviceDnInformation: %[DeviceName=SEP00077Dxxxxxx][DeviceType=564][StationDesc=TESTPHONE 6945][StationDn=7777, 7700,][AppID=Cisco CallManager][ClusterID=StandAloneCluster][NodeID=callmanager1]: List of directory numbers (DN) associated with this device

Sep 02 13:41:58 callmanager1 local7 6 : 4154: callmanager1.sg.local Sep 02 2015 11:41:58 UTC : %UC_-6-LastOutOfServiceInformation: %[DeviceName=SEP00077dxxxxxx][DeviceIPv4Address=192.168.10.123/32][IPv4DefaultGateway=192.168.10.1][DeviceIPv6Address=][IPv6DefaultGateway=][ModelNumber=CP-6945][NeighborIPv6Address=][NeighborIPv4Address=192.168.111.7][NeighborDeviceID=SWITCH2][NeighborPortID=GigabitEthernet1/0/14][DHCPv4Status=1][DHCPv6Status=1][TFTPCfgStatus=1][DNSStatusUnifiedCM1=1][DNSStatusUnifiedCM2=1][VoiceVLAN=10][UnifiedCMIPAddress=192.168.20.20][LocalPort=15753][TimeStamp=1441194083][ReasonForOutOfService=10][LastProtocolEventSent=0x27][LastProtocolEventReceived=0x100][AppID=Cisco CallManager][ClusterID=StandAloneCluster][NodeID=callmanager1]: Information related to the last out-of-service event

Sep 02 13:41:58 callmanager1 local7 6 : 4155: callmanager1.sg.local Sep 02 2015 11:41:58 UTC : %UC_CALLMANAGER-6-StationConnectionError: %[DeviceName=SEP00077Dxxxxxx][ReasonCode=4][AppID=Cisco CallManager][ClusterID=StandAloneCluster][NodeID=callmanager1]: Station device is closing the connection

Sep 02 13:41:58 callmanager1 local7 3 : 4156: callmanager1.sg.local Sep 02 2015 11:41:58 UTC : %UC_CALLMANAGER-3-EndPointUnregistered: %[DeviceName=SEP00077Dxxxxxx][IPAddress=192.168.10.123][Protocol=SCCP][DeviceType=564][Description=TESTPHONE 6945][Reason=16][MACAddress=00077Dxxxxxx][IPAddrAttributes=3][AppID=Cisco CallManager][ClusterID=StandAloneCluster][NodeID=callmanager1]: An endpoint has unregistered

Sep 02 13:41:58 callmanager1 local7 6 : 4160: callmanager1.sg.local Sep 02 2015 11:41:58 UTC : %UC_CALLMANAGER-6-EndPointRegistered: %[DeviceName=SEP00077Dxxxxxx][IPAddress=192.168.10.123][Protocol=SCCP][DeviceType=564][PerfMonObjType=2][Description=TESTPHONE 6945][UserID=testuser][LoadID=SCCP6945.9-4-1-3][AssociatedDNs=7777,7700][MACAddress=00077Dxxxxxx][IPAddrAttributes=3][ActiveLoadId=SCCP6945.9-4-1-3][AppID=Cisco CallManager][ClusterID=StandAloneCluster][NodeID=callmanager1]: Endpoint registered

Sep 02 13:41:58 callmanager1 local7 6 : 4161: callmanager1.sg.local Sep 02 2015 11:41:58 UTC : %UC_CALLMANAGER-6-DeviceDnInformation: %[DeviceName=SEP00077Dxxxxxx][DeviceType=564][StationDesc=TESTPHONE 6945][StationDn=7777, 7700,][AppID=Cisco CallManager][ClusterID=StandAloneCluster][NodeID=callmanager1]: List of directory numbers (DN) associated with this device

Gordon Ross · ‎09-02-2015

Try looking at the logs on the phone itself. Usually CM-reset-TCP type error is a network problem between device and CUCM.

GTG

Please rate all helpful posts.

Andreas Wittemann · ‎09-02-2015

I know...but there was nothing obvious, no tunnel resets, no connection lost between the branch and HQ, as well no connection problem on the branches LAN...this is what made me so curious.

And i checked the phones logs also, this is what i saw there, nothing more visible:

Sep 02 06:54:21 12: Name=SEP00077Dxxxxxx Load=SCCP6945.9-4-1-3 Last=CM-reset-TCP

Sep 02 06:54:40 12: Name=SEP00077Dxxxxxx Load=SCCP6945.9-4-1-3 Last=CM-reset-TCP

Sep 02 07:59:56 12: Name=SEP00077Dxxxxxx Load=SCCP6945.9-4-1-3 Last=CM-reset-TCP

Sep 02 08:00:01 12: Name=SEP00077Dxxxxxx Load=SCCP6945.9-4-1-3 Last=CM-reset-TCP

Sep 02 13:41:23 12: Name=SEP00077Dxxxxxx Load=SCCP6945.9-4-1-3 Last=CM-reset-TCP

Sep 02 13:41:58 12: Name=SEP00077Dxxxxxx Load=SCCP6945.9-4-1-3 Last=CM-reset-TCP

Mohammed al Baqari · ‎09-02-2015

Hi,

CM-reset-TCP means that CUCM initiates the connection reset. First thing is to check the DB replication between CUCM nodes from Cisco Unified Reporting.

If the DB replication status on both nodes is 2, worth looking at the CPU usage of both nodes.

Andreas Wittemann · ‎09-03-2015

Hi Mohammad,

thanks for your hints, i checked it...both seem to be OK...

Really annoying to not find anything really fingerpointing at some part of the system ;)

Jonathan Unger · ‎09-06-2015

CM-reset-TCP does not necessarily mean that CUCM was the device that sent the Reset.

This behaviour can also occur if there is a firewall in the path between the phone and CUCM that is re-setting the communication.

If you have checked the CUCM logs and there is no evidence of a reset being sent from CUCM, there could be another device in the path doing it.

You confirm this by taking a packet capture on the UCM server that the phone is registered to (only capture traffic between CUCM and 1 phone having the issue). There is a great article on how to run the packet captures here https://supportforums.cisco.com/document/44376/packet-capture-cucm-appliance-model .

Once you have setup the capture, and re-produced the issue you can gather the pcap from CUCM and confirm for sure if it is the one sending the TCP reset. If it is not, and the phone logs indicate a reset was sent, you know it was an intermediary device.

If CUCM did send the reset, the cause for the reset should be in the detailed CM trace.

avinsrid89 · ‎09-03-2015

Hi Andreas,

Check the CCM Service traces on why CUCM did / is doing a phone reset.

I can assist if needed, however this can be due to a DB mismatch in the device table for the phones.

CCM Details traces should you however.

Kindly rate useful posts!

~Avinash

Andreas Wittemann · ‎09-04-2015

Which services should be most relevant?

Mohammed al Baqari · ‎09-04-2015

Ccm service

Mohammed al Baqari · ‎09-04-2015

Hi,

From ucm reporting can you get 1 week historocal report for cpu and db replication.

Also try to set alerts for cpu spikes and db replication failures and lets see if that syncs with the phone resets.

avinsrid89 · ‎09-04-2015

CCM Service + Event Viewer Application Log

~Avinash

MurrayAhern4489 · ‎05-08-2019

Good morning, I came across this post as I am experiencing the exact same issue with my 6945 phones frequently restarting. Was a resolution every find on this problem.

Thank you, Murray

Strange error with CP-6945, Last=CM-reset-TCP