Wednesday, 28 June 2017

Phone Reason for Out of Service Codes

Examine jabber.log or Debug Display on a phone's web server to look for entries after a disconnect occurred.
Then refer to this list, which is scraped from CUCM Serviceability > Alarm > Definition > CallManager Alarm Catalog > Phone > Find > LastOutOfServiceInformation.
Note that CUCM 11.5 added some more reason codes but the alarm catalogue hasn't been updated, there's a bug listing for this: CSCvb63000

10   --  TCPtimedOut - The TCP connection to the Cisco Unified Communication Manager experienced a timeout error
12   --  TCPucmResetConnection - The Cisco Unified Communication Manager reset the TCP connection
13   --  TCPucmAbortedConnection - The Cisco Unified Communication Manager aborted the TCP connection
14   --  TCPucmClosedConnection - The Cisco Unified Communication Manager closed the TCP connection
15   --  SCCPKeepAliveFailure - The device closed the connection due to a SCCP KeepAlive failure
16   --  TCPdeviceLostIPAddress - The connection closed due to the IP address being lost.  This may be due to the DHCP Lease expiring or the detection of IP address duplication. Check that the DHCP Server is online and that no duplication has been reported by the DHCP Server
17   --  TCPDeviceRegsistrationTimedOut - The device closed the TCP connection due to a registration timeout
18   --  TCPclosedConnectHighPriorityUcm - The device closed the TCP connection in order to reconnect to a higher priority Cisco Unified CM
20   --  TCPclosedUserInitiatedReset - The device closed the TCP connection due to a user initiated reset
22   --  TCPclosedUcmInitiatedReset - The device closed the TCP connection due to a reset command from the Cisco Unified CM
23   --  TCPclosedUcmInitiatedRestart - The device closed the TCP connection due to a restart command from the Cisco Unified CM
24   --  TCPClosedRegistrationReject - The device closed the TCP connection due to receiving a registration rejection from the Cisco Unified CM
25   --  RegistrationSuccessful - The device has initialized and is unaware of any previous connection to the Cisco Unified CM
26   --  TCPclosedVlanChange - The device closed the TCP connection due to reconfiguration of IP on a new Voice VLAN
27   --  TCPclosedPowerSavePlus - The device closed the TCP connection in order to enter Power Save Plus mode
100  --  ConfigVersionMismatch - The device detected a version stamp mismatch during registration Cisco Unified CM
104  --  TCPclosedApplyConfig - The device closed the TCP connection to restart triggered internally by the device to apply the configuration changes
105  --  TCPclosedDeviceRestart - The device closed the TCP connection due to a restart triggered internally by the device because device failed to download the configuration or dial plan file
106  --  TCPsecureConnectionFailed - The device failed to setup a secure TCP connection with Cisco Unified CM
107  --  TCPclosedDeviceReset - The device closed the TCP connection to set the inactive partition as active partition, then reset, and come up from the new active partition
108  --  VpnConnectionLost - The device could not register to Unified CM because VPN connectivity was lost
200  --  ClientApplicationClosed - The device was unregistered because the client application was closed
201  --  OsInStandbyMode - The device was unregistered because the OS was put in standby mode
202  --  OsInHibernateMode - The device was unregistered because the OS was put in hibernate mode
203  --  OsInShutdownMode - The device was unregistered because the OS was shut down
204  --  ClientApplicationAbort - The device was unregistered because the client application crashed
205  --  DeviceUnregNoCleanupTime - The device was unregistered in the previous session because the system did not allow sufficient time for cleanup
206  --  DeviceUnregOnSwitchingToDeskphone - The device was unregistered because the client requested to switch from softphone to deskphone control
207  --  DeviceUnregOnSwitchingToSoftphone - The device is being registered because the client requested to switch from deskphone control to softphone
208  --  DeviceUnregOnNetworkChanged - The device is being unregistered because the client detected a change of network
209  --  DeviceUnregExceededRegCount - The device is being unregistered because the device has exceeded the maximum number of concurrent registrations
210  --  DeviceUnregExceededLoginCount - The device is being unregistered because the client has exceeded the maximum number of concurrent logons

Jabber Log SIP Message Troubleshooting

Jabber logs a great deal of information locally, but it can be quite cryptic. So it really helps to know which terms to search for, this is quick run through some SIP troubleshooting based on Jabber's logs.

On Windows the logs are stored in C:\Users\<username>\AppData\Local\Cisco\Unified Communications\Jabber\CSF\Logs.
To find SIP messaging embedded in the logs, search jabber.log for the term "sipio". The direction of the SIP message is shown by sipio-sent or sipio-recv.


The SIP transaction below shows Jabber periodically re-registering to its primary CUCM server. The difference in Expires values in the Register & the OK is because the default SIP Station Keepalive is 120s & the default SIP Profile Timer Register Expires is 3600s.
Note that Jabber & other Cisco SIP phones also periodically send a Register with Expires: 0 to their backup CUCM server(s) as a keepalive to track which are also active. How often is controlled by the SIP Profile Timer Keep Alive Expires value, default 120s.

2017-06-13 13:41:57,424 DEBUG [0x00002294] [p\sipcc\core\sipstack\ccsip_debug.c(326)] [csf.sip-call-control] [platform_print_sip_msg] - sipio-sent---> REGISTER sip:172.16.1.10 SIP/2.0
Via: SIP/2.0/TCP 10.1.2.50:61794;branch=z9hG4bK000025d0
From: <sip:13370@172.16.1.10>;tag=e4a7a07eecf3000d0000466b-0000618d
To: <sip:13370@172.16.1.10>
Call-ID: e4a7a07e-ecf30005-00006f7f-000077e9@10.1.2.50
Max-Forwards: 70
Date: Tue, 13 Jun 2017 08:11:57 GMT
CSeq: 105 REGISTER
User-Agent: Cisco-CSF
Contact: <sip:ab0f6d1c-e8ca-7fdb-2cb6-ae2cb788f8ea@10.1.2.50:61794;transport=tcp>;+sip.instance="<urn:uuid:00000000-0000-0000-0000-e4a7a07eecf3>";+u.sip!devicename.ccm.cisco.com="csfAUser";+u.sip!model.ccm.cisco.com="503";video;bfcp
Supported: replaces,join,sdp-anat,norefersub,resource-priority,extended-refer,X-cisco-callinfo,X-cisco-serviceuri,X-cisco-escapecodes,X-cisco-service-control,X-cisco-srtp-fallback,X-cisco-monrec,X-cisco-config,X-cisco-sis-7.0.0,X-cisco-xsi-8.5.1,X-cisco-graceful-reg,X-cisco-duplicate-reg
Content-Length: 0
Expires: 3600

...

2017-06-13 13:41:57,427 DEBUG [0x00002294] [p\sipcc\core\sipstack\ccsip_debug.c(326)] [csf.sip-call-control] [platform_print_sip_msg] - sipio-recv<--- SIP/2.0 100 Trying
Via: SIP/2.0/TCP 10.1.2.50:61794;branch=z9hG4bK000025d0
From: <sip:13370@172.16.1.10>;tag=e4a7a07eecf3000d0000466b-0000618d
To: <sip:13370@172.16.1.10>
Date: Tue, 13 Jun 2017 08:11:57 GMT
Call-ID: e4a7a07e-ecf30005-00006f7f-000077e9@10.1.2.50
CSeq: 105 REGISTER
Content-Length: 0

...

2017-06-13 13:41:57,429 DEBUG [0x00002294] [p\sipcc\core\sipstack\ccsip_debug.c(326)] [csf.sip-call-control] [platform_print_sip_msg] - sipio-recv<--- SIP/2.0 200 OK
Via: SIP/2.0/TCP 10.1.2.50:61794;branch=z9hG4bK000025d0
From: <sip:13370@172.16.1.10>;tag=e4a7a07eecf3000d0000466b-0000618d
To: <sip:13370@172.16.1.10>;tag=1293437236
Date: Tue, 13 Jun 2017 08:11:57 GMT
Call-ID: e4a7a07e-ecf30005-00006f7f-000077e9@10.1.2.50
Server: Cisco-CUCM10.5
CSeq: 105 REGISTER
Expires: 120
Contact: <sip:ab0f6d1c-e8ca-7fdb-2cb6-ae2cb788f8ea@10.1.2.50:61794;transport=tcp>;+sip.instance="<urn:uuid:00000000-0000-0000-0000-e4a7a07eecf3>";+u.sip!devicename.ccm.cisco.com="csfAUser";+u.sip!model.ccm.cisco.com="503";video;bfcp
Supported: X-cisco-srtp-fallback,X-cisco-sis-7.1.1
Content-Length: 0


When Jabber or a SIP phone's TCP connection with the primary CUCM breaks, it will attempt to register with the secondary, tertiary or SRST server (in that order).
In the background it it will keep trying to re-establish a TCP connection to its primary CUCM, if this succeeds it will send a Register with Expires: 0. If the primary CUCM responds with 200 OK, the phone will send a Refer with a Refer-To: <urn:X-cisco-remotecc:token-registration> header to re-register with the primary, which will respond with 202 Accepted. Note that the Connection Monitor Duration can come into play here, the default value of 120s (configured in Device Pool) controls failback once connectivity is restored.
Below Jabber is registered to 172.16.1.10, but then re-registers to 172.16.0.10 via this Refer mechanism:

2017-06-13 13:42:02,422 DEBUG [0x00002294] [p\sipcc\core\sipstack\ccsip_debug.c(326)] [csf.sip-call-control] [platform_print_sip_msg] - sipio-sent---> REFER sip:172.16.0.10 SIP/2.0
Via: SIP/2.0/TCP 10.1.2.50:61887;branch=z9hG4bK000001c3
From: <sip:13370@172.16.0.10>;tag=e4a7a07eecf3000e00005115-000075c2
To: <sip:13370@172.16.0.10>
Call-ID: e4a7a07e-ecf3000f-00002ba3-00000622@10.1.2.50
Max-Forwards: 70
Date: Tue, 13 Jun 2017 08:12:02 GMT
CSeq: 102 REFER
User-Agent: Cisco-CSF
Contact: <sip:ab0f6d1c-e8ca-7fdb-2cb6-ae2cb788f8ea@10.1.2.50:61887;transport=tcp>;+sip.instance="<urn:uuid:00000000-0000-0000-0000-e4a7a07eecf3>";+u.sip!devicename.ccm.cisco.com="csfAUser";+u.sip!model.ccm.cisco.com="503";video;bfcp
Remote-Party-ID: "Anonymous User" <sip:13370@172.16.1.10>;party=calling;id-type=subscriber;privacy=off;screen=yes
Require: norefersub
Refer-To: <urn:X-cisco-remotecc:token-registration>
Referred-By: <sip:13370@172.16.1.10>
Content-Length: 0

...

2017-06-13 13:42:02,429 DEBUG [0x00002294] [p\sipcc\core\sipstack\ccsip_debug.c(326)] [csf.sip-call-control] [platform_print_sip_msg] - sipio-recv<--- SIP/2.0 202 Accepted
Via: SIP/2.0/TCP 10.1.2.50:61887;branch=z9hG4bK000001c3
From: <sip:13370@172.16.0.10>;tag=e4a7a07eecf3000e00005115-000075c2
To: <sip:13370@172.16.0.10>;tag=630562267
Date: Tue, 13 Jun 2017 08:12:02 GMT
Call-ID: e4a7a07e-ecf3000f-00002ba3-00000622@10.1.2.50
CSeq: 102 REFER
Contact: <sip:172.16.0.10:5060;transport=tcp>
Content-Length: 0


Shortly after this in jabber.log is a LastOutOfServiceInformation alarm in XML format with more information. Here Jabber unregistered from 172.16.1.10 due to reason for out of service code 18 - the device closed the TCP connection in order to reconnect to a higher priority CUCM:

2017-06-13 13:42:02,429 DEBUG [0x00002294] [honewrapper\ccapi_plat_api_impl.cpp(851)] [csf.ecc.sipcc] [platSetAlarmXML] - Last OOS Alarm: <?xml version="1.0" encoding="UTF-8" ?>
<x-cisco-alarm>
<Alarm Name="LastOutOfServiceInformation">
<ParameterList>
<String name="DeviceName">csfAUser</String>
<String name="DeviceIPv4Address">10.1.2.50 / 0</String>
<String name="IPv4DefaultGateway">10.21.20.2</String>
<String name="DeviceIPv6Address"></String>
<String name="IPv6DefaultGateway"></String>
<String name="ModelNumber">CSF</String>
<String name="NeighborIPv4Address"></String>
<String name="NeighborIPv6Address"></String>
<String name="NeighborDeviceID"></String>
<String name="NeighborPortID"></String>
<Enum name="DHCPv4Status">1</Enum>
<Enum name="DHCPv6Status">3</Enum>
<Enum name="TFTPCfgStatus">1</Enum>
<Enum name="DNSStatusUnifiedCM1">4</Enum>
<Enum name="DNSStatusUnifiedCM2">4</Enum>
<Enum name="DNSStatusUnifiedCM3">3</Enum>
<String name="VoiceVLAN">0</String>
<String name="UnifiedCMIPAddress">172.16.1.10</String>
<String name="LocalPort">61794</String>
<String name="TimeStamp">1497341522</String>
<Enum name="ReasonForOutOfService">18</Enum>
<String name="LastProtocolEventSent"></String>
<String name="LastProtocolEventReceived">Rcvd:SIP/2.0 202 Accepted  Cseq:102 REFER CallId:e4a7a07e-ecf3000f-00002ba3-00000622@10.1.2.50    </String>
</ParameterList>
</Alarm>
</x-cisco-alarm>


Below is a midcall Notify from CUCM to update the local & remote identities for the call. Note the Content-Type: application/dialog-info+xml indicates the dialogue information (e.g. call state) within the Notify message body is sent as XML.
For the local identity Cisco's Blended Identity mechanism is in use, with the attribute ";x-cisco-number=13370" appended to the URI to provide both the calling directory number as well as the calling URI.

2017-06-13 11:34:58,120 DEBUG [0x0000210c] [p\sipcc\core\sipstack\ccsip_debug.c(326)] [csf.sip-call-control] [platform_print_sip_msg] - sipio-recv<--- NOTIFY sip:ab0f6d1c-e8ca-7fdb-2cb6-ae2cb788f8ea@10.1.2.50:64877;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 172.16.0.10:5060;branch=z9hG4bKd47854c9bb677
From: <sip:172.16.0.10>;tag=220660293
To: <sip:13370@10.1.2.50>
Call-ID: 394a6680-93f1808a-85997-86001dac@172.16.0.10
CSeq: 101 NOTIFY
Max-Forwards: 70
Date: Tue, 13 Jun 2017 06:04:58 GMT
Event: dialog
Subscription-State: active
Contact: <sip:172.16.0.10:5060;transport=tcp>
Content-Type: application/dialog-info+xml
Content-Length: 950

<dialog-info xmlns="urn:ietf:parmams:xml:ns:dialog-info"
 xmlns:call="urn:x-cisco:parmams:xml:ns:dialog-info:dialog:callinfo-dialog"
 xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
 version="4565" state="partial" entity="sip:13370@172.16.0.10">
  <dialog id="375052" call-id="00ccfc98-065b009e-056cf773-0230b189@10.11.4.40" local-tag="00ccfc98065b1a0d44dd805c-7dcb36ea" remote-tag="16333562~e3ae9800-5645-423f-a6a7-991668844a33-49723566" direction="initiator">
    <state>proceeding</state>
    <call:instance>1</call:instance>
    <call:orientation>To</call:orientation>
    <call:lock>unlocked</call:lock>
    <duration>1</duration>
    <call:gci>2-7240322</call:gci>
    <local>
      <identity display="Anonymous User">sip:Anonymous.User@somewhere.com;x-cisco-number=13370</identity>
    </local>

    <remote>
      <identity display="Reception Desk">sip:13821@172.16.0.10:5060</identity>
    </remote>
  </dialog>
</dialog-info>

...

2017-06-13 11:34:58,120 DEBUG [0x0000210c] [p\sipcc\core\sipstack\ccsip_debug.c(326)] [csf.sip-call-control] [platform_print_sip_msg] - sipio-sent---> SIP/2.0 200 OK
Via: SIP/2.0/TCP 172.16.0.10:5060;branch=z9hG4bKd47854c9bb677
From: <sip:172.16.0.10>;tag=220660293
To: <sip:13370@10.1.2.50>
Call-ID: 394a6680-93f1808a-85997-86001dac@172.16.0.10
Date: Tue, 13 Jun 2017 06:04:58 GMT
CSeq: 101 NOTIFY
Content-Length: 0