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
No comments:
Post a Comment