Jabber MRA cannot connect to phone services

stephen.widjaja · ‎03-17-2016

Hello,

I have problem with Jabber MRA phone services. IM&P server already connected, i can chat and the presence is active and from internal everything works fine.

Attached the Expressway-C and Expressway-E log from diagnostic logging.

Here's what i get from the Expressway Core log :

2016-03-18T10:37:52+07:00 ewcore tvcs: UTCTime="2016-03-18 03:37:52,154" Module="network.sip" Level="INFO": Action="Received" Local-ip="10.0.146.111" Local-port="25342" Src-ip="10.0.146.112" Src-port="7002" Detail="Receive Response Code=401, Method=OPTIONS, CSeq=49508, To=sip:10.0.146.112:7002, Call-ID=1a9465009b4a7bea@10.0.146.111, From-Tag=2d60d8a54368916f, To-Tag=a22db56e2788607c, Msg-Hash=6067509367321149832"
2016-03-18T10:37:52+07:00 ewcore tvcs: UTCTime="2016-03-18 03:37:52,154" Module="network.sip" Level="DEBUG": Action="Received" Local-ip="10.0.146.111" Local-port="25342" Src-ip="10.0.146.112" Src-port="7002" Msg-Hash="6067509367321149832"
SIPMSG:
|SIP/2.0 401 Unauthorised
Via: SIP/2.0/TCP 10.0.146.111:5060;branch=z9hG4bKca591ec0b9e96167cac09b7825ef48e214923;received=10.0.146.111;rport=25342
Call-ID: 1a9465009b4a7bea@10.0.146.111
CSeq: 49508 OPTIONS
From: <sip:10.0.146.111>;tag=2d60d8a54368916f
To: <sip:10.0.146.112:7002>;tag=a22db56e2788607c
Server: TANDBERG/4132 (X8.7)
WWW-Authenticate: Digest realm="Traversal Zone", nonce="7f39b9db989f9d7bbe2edf5c0a1e7a3962f130e51b50b073589b0d3a7c4e", opaque="AQAAAC5AJ8ihzAINCUVOmsCl6OFd+7UL", stale=FALSE, algorithm=MD5, qop="auth"
Content-Length: 0

2016-03-18T10:37:52+07:00 ewcore traffic_server[29909]: UTCTime="2016-03-18 03:37:52,553" Module="network.http.trafficserver" Level="INFO": Detail="Sending Request" Txn-id="1122" Dst-ip="10.0.146.105" Dst-port="6972" Msg="GET /jabber-config.xml HTTP/1.1"
2016-03-18T10:37:52+07:00 ewcore traffic_server[29909]: UTCTime="2016-03-18 03:37:52,553" Module="network.http.trafficserver" Level="DEBUG": Detail="Sending Request" Txn-id="1122" Dst-ip="10.0.146.105" Dst-port="6972"
HTTPMSG:
|GET /jabber-config.xml HTTP/1.1
Host: cucm.demo.astra.co.id:6972
Accept: */*
User-Agent: Jabber-OSX-654
X-Forwarded-For: 114.124.4.113, 127.0.0.1
Via: https/1.1 vcs[0A009270] (ATS), http/1.1 vcs[0A00926F] (ATS)

|

2016-03-18T10:37:52+07:00 ewcore traffic_server[29909]: UTCTime="2016-03-18 03:37:52,605" Module="network.http.trafficserver" Level="INFO": Detail="Receive Response" Txn-id="1122" Src-ip="10.0.146.105" Src-port="6972" Msg="HTTP/1.1 404 Not Found"
2016-03-18T10:37:52+07:00 ewcore traffic_server[29909]: UTCTime="2016-03-18 03:37:52,605" Module="network.http.trafficserver" Level="DEBUG": Detail="Receive Response" Txn-id="1122" Src-ip="10.0.146.105" Src-port="6972"
HTTPMSG:
|HTTP/1.1 404 Not Found
Content-length: 0
Content-type: */*

|

2016-03-18T10:37:52+07:00 ewcore traffic_server[29909]: UTCTime="2016-03-18 03:37:52,606" Module="network.http.trafficserver" Level="INFO": Detail="Sending Response" Txn-id="1122" Dst-ip="127.0.0.1" Dst-port="35055" Msg="HTTP/1.1 404 Not Found"
2016-03-18T10:37:52+07:00 ewcore traffic_server[29909]: UTCTime="2016-03-18 03:37:52,606" Module="network.http.trafficserver" Level="DEBUG": Detail="Sending Response" Txn-id="1122" Dst-ip="127.0.0.1" Dst-port="35055"
HTTPMSG:
|HTTP/1.1 404 Not Found
Content-length: 0
Content-type: */*
Date: Fri, 18 Mar 2016 03:37:52 GMT
Age: 0
Connection: keep-alive
Server: CE_C

Jonathan Unger · ‎03-18-2016

Hi There,

The "|SIP/2.0 401 Unauthorised" message you mentioned is totally normal in this case (it occurs 9 times in the EXP-C logs provided).

There is a 4 message transaction that takes place when SIP wants to authenticate an Options message.

Here is a compressed version of your EXP-E log which illustrates this behaviour.

A. EXP-E receives a SIP OPTIONS message from the EXP-C.

2016-03-18T10:37:52+07:00 ewedge tvcs: UTCTime="2016-03-18 03:37:52,153" Module="network.sip" Level="DEBUG":  Action="Received"
 SIPMSG:
 |OPTIONS sip:10.0.146.112:7002;transport=tcp SIP/2.0
 Via: SIP/2.0/TCP 10.0.146.111:5060;branch=z9hG4bKca591ec0b9e96167cac09b7825ef48e214923;rport
 Call-ID: 1a9465009b4a7bea@10.0.146.111
 ...Some Output Removed...

B. EXP-E sends an "Unauthorised" message to the EXP-C asking the EXP-C to authenticate the message.

2016-03-18T10:37:52+07:00 ewedge tvcs: UTCTime="2016-03-18 03:37:52,153" Module="network.sip" Level="DEBUG":  Action="Sent"
SIPMSG:
 |SIP/2.0 401 Unauthorised
 Via: SIP/2.0/TCP 10.0.146.111:5060;branch=z9hG4bKca591ec0b9e96167cac09b7825ef48e214923;received=10.0.146.111;rport=25342
 Call-ID: 1a9465009b4a7bea@10.0.146.111
 ...Some Output Removed...
 WWW-Authenticate: Digest realm="Traversal Zone", nonce="7f39b9db989f9d7bbe2edf5c0a1e7a3962f130e51b50b073589b0d3a7c4e", opaque="AQAAAC5AJ8ihzAINCUVOmsCl6OFd+7UL", stale=FALSE, algorithm=MD5, qop="auth"
 ...Some Output Removed...

C. EXP-C re-sends an authenticated version of the SIP OPTIONS Message to the EXP-E.

2016-03-18T10:37:52+07:00 ewedge tvcs: UTCTime="2016-03-18 03:37:52,156" Module="network.sip" Level="DEBUG":  Action="Received"
SIPMSG:
 |OPTIONS sip:10.0.146.112:7002;transport=tcp SIP/2.0
 Via: SIP/2.0/TCP 10.0.146.111:5060;branch=z9hG4bK2daa4f760b029afd66818220b1beb51e14924;rport
 Call-ID: 1a9465009b4a7bea@10.0.146.111
 ...Some Output Removed...
Authorization: Digest nonce="7f39b9db989f9d7bbe2edf5c0a1e7a3962f130e51b50b073589b0d3a7c4e", realm="Traversal Zone", opaque="AQAAAC5AJ8ihzAINCUVOmsCl6OFd+7UL", algorithm=MD5, uri="sip:10.0.146.112:7002;transport=tcp", username="traversaladmin", response="2c995a59ae100b934dda680409ae2e45", qop=auth, cnonce="1376a4b3ff6e7c75bcb928d5d44556dbd11c90ca2cb95ef0a6d01e2d1bb6", nc=00000001
 ...Some Output Removed...

D. EXP-E then sends a 200 OK back to the EXP-C.

2016-03-18T10:37:52+07:00 ewedge tvcs: UTCTime="2016-03-18 03:37:52,163" Module="network.sip" Level="DEBUG":  Action="Sent"
 SIPMSG:
 |SIP/2.0 200 OK
 Via: SIP/2.0/TCP 10.0.146.111:5060;branch=z9hG4bK2daa4f760b029afd66818220b1beb51e14924;received=10.0.146.111;rport=25342
 Call-ID: 1a9465009b4a7bea@10.0.146.111
 ...Some Output Removed...

Regarding the "404 Not Found Log Messages". The 404 is in response of the EXP-C request to access the jabber-config.xml file on your TFTP server (10.0.146.105) on port 6972 (new port used in UCM 11).

Do you use a jabber-config.xml file? If so, are you able to access it at the following URL?

https://10.0.146.105:6972/jabber-config.xml

If you have uploaded a jabber-config.xml file and it does not show up when manually requesting the above URL, please restart the tomcat service and deactivate/reactivate the TFTP server on the applicable CUCM nodes and try again.

Based on the EXP-C logs, it looks like your CSF device configuration (CSFjabberdemo4.cnf.xml) was successfully downloaded, a 200 OK was received from CUCM.

A few other follow up points:

1. On your EXP-C under "Status > Unified Communications" is "Unified CM registrations" showing as "Configured"?

2. On your EXP-C under "Status > Unified Communications" select "View provisioning sessions". Under the "Unified CM server" column, are any of the server entries appearing in red text?

3. To confirm, when you say from internal everything works fine, you mean that the softphone registers correctly?

4. It looks like you are running Expressway version X8.7 and CUCM 11.0.1, is this correct?

5. Have you tried restarting your Expressways?

stephen.widjaja · ‎03-19-2016

Hi Jonathan,

Thankyou for your explanation.

The answer below to reply your previous question :

1. Its properly configured

2. No, it didnt appear as red text

3. Yes, device can registered properly when in LAN

4. Yes, youre correct

5. I'd tried to restart the expressway twice

Fyi, i didnt create any jabber-config. I guess the device can't get the tftp information. But thats just my presumption.

Cheers

Jonathan Unger · ‎03-20-2016

It would be helpful if you could also post your jabber client troubleshooting log (Help > Report a problem) after a failed softphone registration.

One last thing, from the jabber client, when you look at Help > Show connection status, under the "Softphone" section, what does it say for the Status, Protocol, and Address?

stephen.widjaja · ‎03-20-2016

Hi Jonathan,

PFA for the Jabber Client Troubleshooting log and connection status.

Jonathan Unger · ‎03-21-2016

Based on the logs you sent I can see the following:

A. A SIP register message went out to the EXP-E from the CSF device and was not responded to (at least there was no response in the CSF log - more on this later).

2016-03-21 13:35:45,024 DEBUG [0x000026c4] [oftphonewrapper\CC_SIPCCService.cpp(342)] [csf.ecc.sipcc] [_SIPCCLoggerFunction] - sipio-sent---> REGISTER sip:cucm.demo.astra.co.id SIP/2.0
Via: SIP/2.0/TLS 10.0.27.216:50718;branch=z9hG4bK00001cc9
From: <sip:5002@cucm.demo.astra.co.id>;tag=3468950133b300020000200b-000054d3
To: <sip:5002@cucm.demo.astra.co.id>
Call-ID: 34689501-33b30002-00002cb3-000061ed@10.0.27.216

B. It appears that the CSF device was able to download its configuration (as confirmed by the 200 OK). The full configuration file for the CSF device was also displayed near the end of the PRT.

2016-03-21 13:36:14,883 INFO  [0x0000040c] [ls\src\http\BasicHttpClientImpl.cpp(373)] [csf.httpclient] [http::executeImpl] - *-----* HTTP response from: https://ewedge.demo.astra.co.id:8443/ZGVtby5hc3RyYS5jby5pZC9odHRwL2N1Y20uZGVtby5hc3RyYS5jby5pZC82OTcw/CSFjabberdemo2.cnf.xml[17] -> 200.
2016-03-21 13:36:14,899 DEBUG [0x0000040c] [src\config\TftpHelper.cpp(134)] [csf.ecc] [ecc::TftpHelper::doRetrieveFile] - HTTP Result: 200

C. Later on in the log it indicates that the SIP TLS connection was closed by the remote end (Expressway-E or any other device in the path).

2016-03-21 13:35:56,289 ERROR [0x000026c4] [ndyiron\src\security\sec_ssl_api.c(2507)] [csf.ecc.handyiron] [secSSLReceive] - SSL_read() : Protocol violation socket error (e.g. remote end closed socket).
2016-03-21 13:35:56,289 DEBUG [0x000026c4] [oftphonewrapper\CC_SIPCCService.cpp(342)] [csf.ecc.sipcc] [_SIPCCLoggerFunction] - SIPCC-SIP_TCP_MSG: sip_tcp_read_socket: CUCM closed TCP connection.
2016-03-21 13:35:56,289 DEBUG [0x000026c4] [oftphonewrapper\CC_SIPCCService.cpp(342)] [csf.ecc.sipcc] [_SIPCCLoggerFunction] - SIPCC-SIP_TRANS: sip_transport_destroy_cc_conn: CC <PRIMARY_CCM>: closing the TCP connection

Immediately after we can see in the CSF Out Of Service Alarm (OOS), that the last SIP message sent from the CSF device was the SIP Register message. To confirm that the CSF device did not receive a response we can see that the "LastProtocolEventReceived" section of the OOS Alarm has no content.

2016-03-21 13:35:56,289 DEBUG [0x000026c4] [honewrapper\ccapi_plat_api_impl.cpp(765)] [csf.ecc.sipcc] [platSetAlarmXML] - Last OOS Alarm: <?xml version="1.0" encoding="UTF-8" ?>
<x-cisco-alarm>
 ...Some Output Removed...
<Enum name="ReasonForOutOfService">12</Enum>
<String name="LastProtocolEventSent">Sent:REGISTER sip:cucm.demo.astra.co.id SIP/2.0  Cseq:101 REGISTER CallId:34689501-33b30002-00002cb3-000061ed@10.0.27.216</String>
<String name="LastProtocolEventReceived"></String>
 ...Some Output Removed...

Unfortunately the CSF logs were not from the same source device or in the same time frame as the diagnostic logs taken from the EXP-E so it is not possible to correlate the EXP logs to the CSF logs.

A few additional points:

1. Is your EXP-E behind NAT, or does it connect directly to the internet?

2. If EXP-E is behind NAT (or a firewall), can you confirm that the firewall does not perform any SIP inspection (can you also confirm the vendor of firewall)? This also includes any type of SIP inspection between the EXP-C and the EXP-E.

3. On the EXP-C please you try the following:

a. Navigate to "Configuration > Unified Communications > Unified CM Servers"

b. Delete all Unified CM servers in the list.

c. Re-Add the UCM publisher node (it should automatically discover the rest of the cluster nodes).

d. Restart the EXP-C and see if there is any improvement in the softphone registration.

stephen.widjaja · ‎03-21-2016

Hi Jonathan,

thanks for your reply. Below is to answer your points :

1 & 2. My Exp-E server is behind NAT and deployed with dual NIC. FYI, the firewall didnt perform any SIP inspection

3. I will try this

Thanks.

Jonathan Unger · ‎03-22-2016

Hi There,

Any luck with your expressways?

stephen.widjaja · ‎03-22-2016

Hi Jonathan,

No luck here. I think its because of SIP Inspection. I try to verify again with my customer.

But from your perspective, all of my configuration is already correct right?

Jonathan Unger · ‎03-22-2016

Yes, it could be an issue related to their firewall.

It would be interesting to grab a diagnostic log with packet capture on the EXP-C/EXP-E as well as the Tshoot log from the jabber client while reproducing the issue.

That way we know if the jabber client receives a TCP reset from the far end and we don't see it in the EXP-E packet capture, there is another device in the path sending the reset (could be firewall).

Also to confirm, is the static NAT mode on the EXP-E set to ON and configured with an external NAT address?

stephen.widjaja · ‎03-23-2016

PFA my IP configuration on Expressway-E and last log that i capture.

Jonathan Unger · ‎03-23-2016

Thanks for gathering all of those traces!

The following breakdown compares log snippets to parts of the wireshark capture from the EXP-E LAN2 interface (Wireshark adjusted -10 hours, +3 seconds to match with jabber log timestamps).

A. Jabber client opens a SIP connection to the EXP-E on port 5061 (source port 61732).

Jabber Log:

2016-03-23 11:08:17,779 DEBUG [0x00002154] [oftphonewrapper\CC_SIPCCService.cpp(342)] [csf.ecc.sipcc] [_SIPCCLoggerFunction] - SIPCC-SIP_CC_CONN: sip_transport_setup_cc_conn: <PRIMARY_CCM>: CC TCP socket opened: to <202.46.131.118>:<5061>, local_port: 61732 handle=<6692>
2016-03-23 11:08:17,779 INFO  [0x00002154] [oftphonewrapper\CC_SIPCCService.cpp(339)] [csf.ecc.sipcc] [_SIPCCLoggerFunction] - set_active_ccm: ccm=PRIMARY_CCM  port=61732

B. Jabber client sends a SIP register message at 11:08:19 which is never received by the EXP-E. No record of the packet in the EXP-E logs, or in the PCAP as seen below.

Jabber Log:

2016-03-23 11:08:19,984 DEBUG [0x00002154] [oftphonewrapper\CC_SIPCCService.cpp(342)] [csf.ecc.sipcc] [_SIPCCLoggerFunction] - sipio-sent---> REGISTER sip:cucm.demo.astra.co.id SIP/2.0

C. Jabber client times out the SIP registration due to no response and marks the CUCM servers as unhealthy.

Jabber Log:

2016-03-23 11:08:22,547 DEBUG [0x00002828] [TelephonyAdapterAuthentication.cpp(1234)] [TelephonyAdapter] [TelephonyAdapter::Connect] - Failed to connect with CUCM [error: eDeviceRegTimedOut]
2016-03-23 11:08:22,547 DEBUG [0x000011c4] [\impl\TelephonyServerHealthImpl.cpp(267)] [csf-unified.telephony.TelephonyServerHealthImpl] [TelephonyServerHealthImpl::updateHealth] - updating health with serverType [CucmSoftphone] serverHealthStatus [Unhealthy] serverConnectionStatus [Disconnected] serverAddress [cucm.demo.astra.co.id (CCMCIP - Expressway)] serviceEventCode [UnknownConnectionError] transportProtocol [SIP]

Based on what we can see in the logs and PCAP, it looks like something is interfering with the SIP messaging between the MRA client and the EXP-E.

Please double check with your customer that they do not have a firewall attempting to inspect the traffic on 5061.

Ben Morgan · ‎06-22-2016

Hi There,

Im seeing very similar behaviour when trying to register a Jabber client through a Checkpoint firewall.

I can see the REGISTER being sent in the jabber logs and also the relevant packet (TLS port5061) from my laptop, however it seems like the firewall is replying the TLS packet as the EXPE never receives it.

The firewall administrator is certain the checkpoint is working as per normal and dropping anything.. However, although its not dropping packets.. its intercepting packets and replying on behalf of the EXPE device.

Has anyone configure Jabber via a Checkpoint firewall, what inspection settings etc need to be configured.

cheers

Ben

Jonathan Unger · ‎06-22-2016

Hi Ben,

We have seen tons of issues with SIP and Palo Alto firewalls. The main problem is that the dropped SIP packets do not show up in the PA logs. The only way to get them is to run a PCAP on the PA and look at the special "dropped packets" PCAP file that the FQ generates.

The solution for all of the SIP related PA issues I have seen is to remove SIP inspection on the PA and write an application override for SIP. There is an article on the PA site which hopefully can help you accomplish this.

https://live.paloaltonetworks.com/t5/Configuration-Articles/How-to-Create-an-Application-Override-Policy/ta-p/60044

Please let us know if this helps.

Ben Morgan · ‎06-22-2016

Thanks Jonathon, this will come in handy as I'm also having MRA issues with SIP Signalling via a PA device.

Do you have any references for Checkpoint Firewall?

Thanks

Ben