I am having problems with my Cisco CME. I have a handful off 7925 and 7921 phones. They are randomly just switching themselves off and it is not hardware related (the problem has happened to almost all the phones at random times).
I have setup debugging on my CME and full debugging on the phones themselves. None of the log files reveal anything, the phones just die without logging anything and the CME only see's the KeepAlives drop before reporting a abnormal deregistration.
The only real pattern I can see is that the phones log some SRST messages exactly 5 seconds before the phone dies. The phones do log these messages every 30 odd seconds so it could be a coincidence but it is the only thing I have to go off right now.
The thing is my CME is not even configured for SRST, but the phones still show a SRST server under CallManger2. I know that we used to have CUCM before my time here, but it was replaced by CME for some reason I dont know. The IP address showing up under CallManager2 though is the IP address of my main switch which does nothing apart from layer 3 routing.
How can I remove the old SRST record from the phones to rule out this as being some sort of bug which is crashing my phones? I have looked at the .cnf.xml files and they only list my CME, there is no SRST record in the config.
Here are the related IP addresses,
Phone from testing: 192.168.3.119
CME - 192.168.3.4
Old CUCM - 192.168.3.10
Layer 3 switch - 192.168.3.1
Here is my show telephone-service all,
CONFIG (Version=8.6)
=====================
Version 8.6
Max phoneload sccp version 17
Max dspfarm sccp version 18
Cisco Unified Communications Manager Express
For on-line documentation please see:
http://www.cisco.com/en/US/products/sw/voicesw/ps4625/tsd_products_support_series_home.html
protocol mode default
ip source-address 192.168.3.4 port 2000
ip qos dscp:
ef (the MS 6 bits, 46, in ToS, 0xB8) for media
cs3 (the MS 6 bits, 24, in ToS, 0x60) for signal
af41 (the MS 6 bits, 34, in ToS, 0x88) for video
default (the MS 6 bits, 0, in ToS, 0x0) for serviceservice directed-pickup
no auto-reg-ephone
load 7921 CP7921G-1.4.2
load 7925 CP7925G-1.4.2
load 7931 SCCP31.9-1-1SR1S
load 7975 SCCP75.9-1-1SR1S
max-ephones 70
max-dn 100
max-conferences 12 gain -6
dspfarm units 0
dspfarm transcode sessions 0
conference software
privacy
no privacy-on-hold
hunt-group report delay 1 hours
hunt-group logout DND
max-redirect 10
cnf-file location: flash:
cnf-file option: PER-PHONE
network-locale[0] US (This is the default network locale for this box)
network-locale[1] US
network-locale[2] US
network-locale[3] US
network-locale[4] US
user-locale[0] US (This is the default user locale for this box)
user-locale[1] US
user-locale[2] US
user-locale[3] US
user-locale[4] US
srst mode auto-provision is OFF
srst ephone template is 0
srst dn template is 0
srst dn line-mode single
phone service g722CodecSupport 2
phone service webAccess 0
phone service phoneBookWebAccess 1
phone service videoCapability 1
phone service ThumbButton1 PTTH2
phone service displayOnWhenIncomingCall 1
phone service daysBacklightNotActive 1,2,3,4,5,6,7
phone service backlightOnTime 07:30
phone service backlightOnDuration 10:00
phone service backlightIdleTimeout 00:01
phone service daysDisplayNotActive 1,2,3,4,5,6,7
phone service displayOnTime 07:30
phone service displayOnDuration 10:00
phone service displayIdleTimeout 00:01
time-format 24
date-format dd-mm-yy
timezone 44 Tokyo Standard Time
secondary-dialtone 9
transfer-pattern .T
keepalive 40 auxiliary 30
timeout interdigit 10
timeout busy 10
timeout ringing 180
timeout transfer-recall 0
timeout ringin-callerid 8
timeout night-service-bell 12
caller-id name-only: enable
system message *****************
web admin system name ********************************
web admin customer name ***************
edit DN through Web: enabled.
edit TIME through web: enabled.
background save interval 10 minutes
Log (table parameters):
max-size: 150
retain-timer: 15
create cnf-files version-stamp Jan 01 2002 00:00:00
transfer-system full-consult
transfer-digit-collect new-call
local directory service: enabled.
Extension-assigner tag-type ephone-tag.
Here are the last bit of logging from the phone before it dies,
2014-01-02 19:30:20:0460 CP-7925G user.info SCCP: <-|ActiveKeepAlive
2014-01-02 19:30:20:0470 CP-7925G user.info SCCP: |->KAAck[1785]
2014-01-02 19:30:21:0360 CP-7925G authpriv.debug AUD: timedPendSignal timedout sec: 1388672927 usec 266173
2014-01-02 19:30:23:0030 CP-7925G authpriv.debug AUD: timedPendSignal timedout sec: 1388672928 usec 922973
2014-01-02 19:30:24:0030 CP-7925G user.info SCCP: SK_GetTcpConnection: Select error (-47) for 17 with time=11
2014-01-02 19:30:24:0040 CP-7925G user.debug SCCP: sk_security_LookServerTrusteList(192.168.3.1:SRST)...
2014-01-02 19:30:24:0050 CP-7925G user.debug secd: appLoop: DO RD, fd 6 (reqS)
2014-01-02 19:30:24:0060 CP-7925G user.notice secd: BEGIN SEC REQ:
2014-01-02 19:30:24:0070 CP-7925G user.notice secd: req-type : 4 (LOOKUP_SRVR)
2014-01-02 19:30:24:0080 CP-7925G user.notice secd: req-id : 5505904 (pid:336/seq:880)
2014-01-02 19:30:24:0090 CP-7925G user.notice secd: clnt-pid : 336
2014-01-02 19:30:24:0100 CP-7925G user.notice secd: max-sec : 120 (timeout)
2014-01-02 19:30:24:0110 CP-7925G user.notice secd: LOOKUP REQ:
2014-01-02 19:30:24:0130 CP-7925G user.notice secd: srvr name : 192.168.3.1
2014-01-02 19:30:24:0130 CP-7925G user.notice secd: srvr type : 3 (SRST)
2014-01-02 19:30:24:0150 CP-7925G user.notice secd: REQ DUMP (84 b):
2014-01-02 19:30:24:0160 CP-7925G user.notice secd: * 04 00 00 00 70 03 54 00 50 01 00 00 78 00 00 00 [....p.T.P...x...]
2014-01-02 19:30:24:0170 CP-7925G user.notice secd: * 03 00 00 00 31 30 2E 32 31 34 2E 33 2E 31 00 00 [....192.168.3.1..]
2014-01-02 19:30:24:0190 CP-7925G user.notice secd: * 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [................]
2014-01-02 19:30:24:0200 CP-7925G user.notice secd: * 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [................]
2014-01-02 19:30:24:0210 CP-7925G user.notice secd: * 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [................]
2014-01-02 19:30:24:0220 CP-7925G user.notice secd: * 00 00 00 00 [....]
2014-01-02 19:30:24:0230 CP-7925G user.notice secd: END SEC REQ
2014-01-02 19:30:24:0240 CP-7925G user.debug secd: appLoop: rd ok, fd 6 (reqS)
2014-01-02 19:30:24:0250 CP-7925G user.debug secd: setFds: chk rd, fd 10 (sslserver)
2014-01-02 19:30:24:0260 CP-7925G user.debug secd: setFds: chk rd, fd 7 (prxy)
2014-01-02 19:30:24:0270 CP-7925G user.debug secd: setFds: chk rd, fd 6 (reqS)
2014-01-02 19:30:24:0280 CP-7925G user.debug secd: setFds: chk rd, fd 5 (cmd)
2014-01-02 19:30:24:0300 CP-7925G user.debug secd: setFds: monitor, rd 4 wr 0
2014-01-02 19:30:24:0300 CP-7925G user.debug secd: setTimeOut: tmo 119s:936ms
2014-01-02 19:30:24:0320 CP-7925G user.warn secd: WARN:lookupSRST: no CTL, treat SRST as non-secure
2014-01-02 19:30:24:0330 CP-7925G user.notice secd: BEGIN SEC REP:
2014-01-02 19:30:24:0340 CP-7925G user.notice secd: req-type : 4 (LOOKUP_SRVR)
2014-01-02 19:30:24:0350 CP-7925G user.notice secd: req-id : 5505904 (pid:336/seq:880)
2014-01-02 19:30:24:0360 CP-7925G user.notice secd: status : 0 (OK)
2014-01-02 19:30:24:0370 CP-7925G user.notice secd: errcode : 0 (NONE)
2014-01-02 19:30:24:0380 CP-7925G user.notice secd: sub-errcode : 0 (N/A)
2014-01-02 19:30:24:0390 CP-7925G user.notice secd: err-desc : <>
2014-01-02 19:30:24:0400 CP-7925G user.notice secd: LOOKUP REP:
2014-01-02 19:30:24:0400 CP-7925G user.notice secd: srvr name : 192.168.3.1
2014-01-02 19:30:24:0410 CP-7925G user.notice secd: srvr type : 3 (SRST)
2014-01-02 19:30:24:0420 CP-7925G user.notice secd: lookup result : 10 (NONSECURE)
2014-01-02 19:30:24:0430 CP-7925G user.notice secd: REP DUMP (156 b):
2014-01-02 19:30:24:0450 CP-7925G user.notice secd: * 04 00 00 00 70 03 54 00 00 00 00 00 00 00 00 00 [....p.T.........]
2014-01-02 19:30:24:0460 CP-7925G user.notice secd: * 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [................]
2014-01-02 19:30:24:0470 CP-7925G user.notice secd: * 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [................]
2014-01-02 19:30:24:0480 CP-7925G user.notice secd: * 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [................]
2014-01-02 19:30:24:0500 CP-7925G user.notice secd: * 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [................]
2014-01-02 19:30:24:0510 CP-7925G user.notice secd: * 00 00 00 00 03 00 00 00 31 30 2E 32 31 34 2E 33 [........192.168.3]
2014-01-02 19:30:24:0520 CP-7925G authpriv.debug AUD: timedPendSignal timedout sec: 1388672930 usec 420633
2014-01-02 19:30:24:0540 CP-7925G user.notice secd: * 2E 31 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [.1..............]
2014-01-02 19:30:24:0550 CP-7925G user.notice secd: * 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [................]
2014-01-02 19:30:24:0560 CP-7925G user.notice secd: * 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [................]
2014-01-02 19:30:24:0570 CP-7925G user.notice secd: * 00 00 00 00 00 00 00 00 0A 00 00 00 [............]
2014-01-02 19:30:24:0580 CP-7925G user.notice secd: END SEC REP
2014-01-02 19:30:24:0600 CP-7925G user.debug secd: appLoop: DO RD, fd 5 (cmd)
2014-01-02 19:30:24:0610 CP-7925G user.debug secd: appLoop: rd ok, fd 5 (cmd)
2014-01-02 19:30:24:0640 CP-7925G user.debug secd: setFds: chk rd, fd 10 (sslserver)
2014-01-02 19:30:24:0650 CP-7925G user.debug SCCP: Server 192.168.3.1 exists in Certificate Trust list....
2014-01-02 19:30:24:0660 CP-7925G user.debug secd: setFds: chk rd, fd 7 (prxy)
2014-01-02 19:30:24:0670 CP-7925G user.debug secd: setFds: chk rd, fd 6 (reqS)
2014-01-02 19:30:24:0680 CP-7925G user.debug secd: setFds: chk rd, fd 5 (cmd)
2014-01-02 19:30:24:0690 CP-7925G user.debug secd: setFds: monitor, rd 4 wr 0
2014-01-02 19:30:24:0700 CP-7925G user.debug secd: setTimeOut: block
2014-01-02 19:30:26:0060 CP-7925G authpriv.debug AUD: timedPendSignal timedout sec: 1388672931 usec 966710
2014-01-02 19:30:27:0940 CP-7925G authpriv.debug AUD: timedPendSignal timedout sec: 1388672933 usec 847467
2014-01-02 19:30:28:0890 CP-7925G user.warn kernel: WLAN_DRVR: 2633.795: Starting cont scan, RSSI = -77
2014-01-02 19:30:28:0900 CP-7925G user.warn kernel: WLAN_DRVR: 2633.811: Restarting continuous scans
2014-01-02 19:30:29:0870 CP-7925G authpriv.debug AUD: timedPendSignal timedout sec: 1388672935 usec 727870
<PHONE DIES HERE>
Here is the log from CME,
Jan 2 19:30:19.800 EST: ephone-2 If GigabitEthernet0/1.3 ETHERNET 192.168.3.119 via ARP
Jan 2 19:30:19.800 EST: ephone-2[1/32][SEP0023AAAAAAAA]:Keepalive socket[32] SEP0023AAAAAAAA
Jan 2 19:30:22.908 EST: Cannot find device entry on socket fd 19 for message 0
Jan 2 19:30:30.736 EST: Cannot find device entry on socket fd 14 for message 0
Jan 2 19:30:34.081 EST: %C3800_ENVM-3-MFAIL_OFF: There is more than one failure with the Power System 2 or this Power System has been turned off.
Jan 2 19:30:36.413 EST: Cannot find device entry on socket fd 17 for message 0
Jan 2 19:30:39.861 EST: VOICE REGISTER POOL-7 has unregistered. Name:SEP000000000338 IP:192.168.3.248 DeviceType:Phon
Jan 2 19:30:42.149 EST: ephone-2[1/32][SEP0023AAAAAAAA]:SkinnyCheckPendingCallBackPhone scan 6 lines
Jan 2 19:30:42.969 EST: Cannot find device entry on socket fd 19 for message 0
Jan 2 19:30:43.149 EST: KeepAlive PROBE on socket [32] ephone-2 ephone address= 192.168.3.119
Jan 2 19:30:50.149 EST: ephone-2[1/32][SEP0023AAAAAAAA]:Keepalive TIMEOUT on socket [32] ephone-2 SEP0023AAAAAAAA
Jan 2 19:30:50.149 EST: ephone-2[1/32][SEP0023AAAAAAAA]:DisAssociate: Closed socket 32 while REGISTERED
Jan 2 19:30:50.149 EST: ephone-2[1/32][SEP0023AAAAAAAA]: DN out-of-service for DN 58 chan 1
Jan 2 19:30:50.149 EST: SkinnyGetCallState for DN 58 chan 1 IDLE
Jan 2 19:30:50.149 EST: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
Jan 2 19:30:50.149 EST: ephone-2[1/32][SEP0023AAAAAAAA]: DN out-of-service for DN 58 chan 2
Jan 2 19:30:50.149 EST: SkinnyGetCallState for DN 58 chan 2 IDLE
Jan 2 19:30:50.149 EST: called DN -1 chan 1, calling DN -1 chan 1 phone 2 incoming s2s:0
Jan 2 19:30:50.149 EST: Bring down DN 58 chan 1 (541) with the following traceback
Jan 2 19:30:50.149 EST: -Traceback= 60585138z 60587E70z 605BF56Cz 605C4DF0z 605C5D98z 604FD790z
Jan 2 19:30:50.149 EST: Skinny DN 58 chan 1 state change to DOWN
Jan 2 19:30:50.149 EST: Bring down DN 58 chan 2 (541) with the following traceback
Jan 2 19:30:50.153 EST: -Traceback= 60585138z 60587E70z 605BF56Cz 605C4DF0z 605C5D98z 604FD790z
Jan 2 19:30:50.153 EST: Skinny DN 58 chan 2 state change to DOWN
Jan 2 19:30:50.153 EST: SkinnySetCTILineStatus: phone 1 dn 58 line status 0 line_removed 0
Jan 2 19:30:50.153 EST: ephone-2[1/32][SEP0023AAAAAAAA]:skinny_delete_socket [32]
Jan 2 19:30:50.153 EST: %IPPHONE-6-UNREGISTER_ABNORMAL: ephone-2:SEP0023AAAAAAAA IP:192.168.3.119 Socket:32 DeviceType:Phone has unregistered abnormally.
