[OpenSIPS-Users] TLS handshake failure

Gregory Massel greg at switchtel.co.za
Mon Jul 6 22:45:56 EST 2020 

Hello

As of five days ago, my OpenSIPS 'SBC' for Microsoft Teams has started 
failing outbound Teams calls (with no changes to the config and after 
everything was working for many weeks prior).

In the direction where OpenSIPS sends the INVITE to Microsoft, 
everything still works normally. It's only problematic in the direction 
where Microsoft sends the INVITE to OpenSIPS.

In my logs, I can see it accepts the first TLS connection, however after 
the INVITE is received, Microsoft tries to establish another TLS 
connection from the same IP and that fails during the TLS handshake.

Jul  7 00:10:02 msteams /usr/sbin/opensips[26344]: INFO:core:probe_max_sock_buff: using snd buffer of 416 kb
Jul  7 00:10:02 msteams /usr/sbin/opensips[26344]: INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 178
Jul  7 00:10:02 msteams /usr/sbin/opensips[26326]: NOTICE:tls_mgm:verify_callback: depth = 2, verify success
Jul  7 00:10:02 msteams /usr/sbin/opensips[26326]: NOTICE:tls_mgm:verify_callback: depth = 1, verify success
Jul  7 00:10:02 msteams /usr/sbin/opensips[26326]: NOTICE:tls_mgm:verify_callback: depth = 0, verify success
Jul  7 00:10:02 msteams /usr/sbin/opensips[26326]: INFO:proto_tls:tls_accept: New TLS connection from 52.114.76.76:2560 accepted
Jul  7 00:10:02 msteams /usr/sbin/opensips[26326]: INFO:proto_tls:tls_dump_cert_info: tls_accept: client TLS certificate subject: /CN=sip.pstnhub.microsoft.com, issuer: /C=US/ST=Washington/L=Redmond/O=Microsoft Corporation/OU=Microsoft IT/CN=Microsoft IT TLS CA 4
Jul  7 00:10:02 msteams /usr/sbin/opensips[26326]: INFO:proto_tls:tls_dump_cert_info: tls_accept: local TLS server certificate subject: /CN=msteams.switchtel.co.za, issuer: /C=US/O=Let's Encrypt/CN=Let's Encrypt Authority X3
Jul  7 00:10:02 msteams /usr/sbin/opensips[26326]: Call from sip:+27105000470 at sip.pstnhub.microsoft.com:5061;user=phone to sip:+27875500000 at samsip1.switchtel.co.za, Socket tls:52.114.76.76:2560 to tls:196.216.192.19:5061, Contact-URI=sip:api-du-b-usea.pstnhub.microsoft.com:443;x-i=346158ef-e50e-4a58-9f08-af7e7813acef;x-c=720af6d686d05fba9a27b237dd0a5ecb/d/8/222b0a8fe57c4584ab717a05b7f0b93f, Teams_Domain=msteams.switchtel.co.za

The logs above show the connection from 52.114.76.76:2560 was 
successful, client and server certificates verified, and the INVITE 
packet was received from Microsoft.
The logs below show the connection from 52.114.76.76:2561 and 
52.114.76.76:2562, just two seconds later, with TLS handshake failure. 
The 2 second gap is the time it takes to send the "200 OK"; that is 
transmitting via the initial connection, however, it seems that 
Microsoft thinks the first connection is dead and attempts to reconnect.

Jul  7 00:10:04 msteams /usr/sbin/opensips[26344]: INFO:core:probe_max_sock_buff: using snd buffer of 416 kb
Jul  7 00:10:04 msteams /usr/sbin/opensips[26344]: INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 179
Jul  7 00:10:04 msteams /usr/sbin/opensips[26328]: ERROR:proto_tls:tls_accept: New TLS connection from 52.114.76.76:2561 failed to accept
Jul  7 00:10:04 msteams /usr/sbin/opensips[26328]: ERROR:proto_tls:tls_read_req: failed to do pre-tls reading
Jul  7 00:10:04 msteams /usr/sbin/opensips[26344]: INFO:core:probe_max_sock_buff: using snd buffer of 416 kb
Jul  7 00:10:04 msteams /usr/sbin/opensips[26344]: INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 179
Jul  7 00:10:04 msteams /usr/sbin/opensips[26328]: ERROR:proto_tls:tls_accept: New TLS connection from 52.114.76.76:2562 failed to accept
Jul  7 00:10:04 msteams /usr/sbin/opensips[26328]: ERROR:proto_tls:tls_read_req: failed to do pre-tls reading

If I take a TShark sample, the first connection gets "Certificate, 
Client Key Exchange, Certificate Verify, Change Cipher Spec, Encrypted 
Handshake Message" while the second and third connections seem to lack 
this part of the TLS handshake:

  22 9.027531791 52.114.76.76 â 196.216.192.19 TLSv1.2 2370 Client Hello
    23 9.027555818 196.216.192.19 â 52.114.76.76 TCP 54 5061 â 7106 [ACK] Seq=1 Ack=2317 Win=63232 Len=0
    24 9.030106811 196.216.192.19 â 52.114.76.76 TLSv1.2 2934 Server Hello, Certificate
    25 9.030278247 196.216.192.19 â 52.114.76.76 TLSv1.2 230 Server Key Exchange, Certificate Request, Server Hello Done
    26 9.223719073 52.114.76.76 â 196.216.192.19 TCP 60 7106 â 5061 [ACK] Seq=2317 Ack=3057 Win=525568 Len=0
    27 9.226831508 52.114.76.76 â 196.216.192.19 TLSv1.2 3823 Certificate, Client Key Exchange, Certificate Verify, Change Cipher Spec, Encrypted Handshake Message
    28 9.226854910 196.216.192.19 â 52.114.76.76 TCP 54 5061 â 7106 [ACK] Seq=3057 Ack=6086 Win=62080 Len=0
    29 9.228225293 196.216.192.19 â 52.114.76.76 TLSv1.2 2248 New Session Ticket, Change Cipher Spec, Encrypted Handshake Message
    30 9.421672079 52.114.76.76 â 196.216.192.19 TCP 60 7106 â 5061 [ACK] Seq=6086 Ack=5251 Win=525568 Len=0
    31 9.423493322 52.114.76.76 â 196.216.192.19 TLSv1.2 2092 Application Data
    32 9.423517425 196.216.192.19 â 52.114.76.76 TCP 54 5061 â 7106 [ACK] Seq=5251 Ack=8124 Win=63232 Len=0
    33 9.424490692 196.216.192.19 â 52.114.76.76 TLSv1.2 478 Application Data
    34 9.583038834 196.216.192.19 â 52.114.76.76 TLSv1.2 931 Application Data
    35 9.661329748 52.114.76.76 â 196.216.192.19 TCP 60 7106 â 5061 [ACK] Seq=8124 Ack=5675 Win=525056 Len=0
    36 9.817636273 52.114.76.76 â 196.216.192.19 TCP 60 7106 â 5061 [ACK] Seq=8124 Ack=6552 Win=524288 Len=0
    37 9.994327854 52.114.132.46 â 196.216.192.19 TLSv1.2 99 Application Data
    38 9.994448210 196.216.192.19 â 52.114.132.46 TLSv1.2 85 Application Data
    39 9.994468209 196.216.192.19 â 52.114.132.46 TLSv1.2 116 Application Data, Application Data
    40 9.994631776 196.216.192.19 â 52.114.132.46 TLSv1.2 85 Application Data
    41 10.251655099 52.114.132.46 â 196.216.192.19 TCP 60 8768 â 5061 [ACK] Seq=46 Ack=94 Win=2051 Len=0
    42 10.294541880 52.114.132.46 â 196.216.192.19 TCP 60 8768 â 5061 [ACK] Seq=46 Ack=125 Win=2051 Len=0
    43 10.585625776 196.216.192.19 â 52.114.76.76 TLSv1.2 1377 Application Data
    44 10.779516806 52.114.76.76 â 196.216.192.19 TCP 66 7107 â 5061 [SYN] Seq=0 Win=64240 Len=0 MSS=1440 WS=256 SACK_PERM=1
    45 10.779555363 196.216.192.19 â 52.114.76.76 TCP 66 5061 â 7107 [SYN, ACK] Seq=0 Ack=1 Win=64240 Len=0 MSS=1460 SACK_PERM=1 WS=128
    46 10.833193731 52.114.76.76 â 196.216.192.19 TCP 60 7106 â 5061 [ACK] Seq=8124 Ack=7875 Win=525568 Len=0
    47 10.971578923 52.114.76.76 â 196.216.192.19 TCP 60 7107 â 5061 [ACK] Seq=1 Ack=1 Win=525568 Len=0
    48 10.971928866 52.114.76.76 â 196.216.192.19 TLSv1.2 210 Client Hello
    49 10.971952878 196.216.192.19 â 52.114.76.76 TCP 54 5061 â 7107 [ACK] Seq=1 Ack=157 Win=64128 Len=0
    50 10.974370873 196.216.192.19 â 52.114.76.76 TLSv1.2 2934 Server Hello, Certificate
    51 10.974542533 196.216.192.19 â 52.114.76.76 TLSv1.2 226 Server Key Exchange, Certificate Request, Server Hello Done
    52 11.086085952 196.216.192.19 â 52.114.76.76 TLSv1.2 1377 Application Data
    53 11.166263352 52.114.76.76 â 196.216.192.19 TCP 60 7107 â 5061 [ACK] Seq=157 Ack=3053 Win=525568 Len=0
    54 11.166844774 52.114.76.76 â 196.216.192.19 TCP 60 7107 â 5061 [FIN, ACK] Seq=157 Ack=3053 Win=525568 Len=0
    55 11.167276748 196.216.192.19 â 52.114.76.76 TCP 54 5061 â 7107 [FIN, ACK] Seq=3053 Ack=158 Win=64128 Len=0
    56 11.170033533 52.114.76.76 â 196.216.192.19 TCP 66 7108 â 5061 [SYN] Seq=0 Win=64240 Len=0 MSS=1440 WS=256 SACK_PERM=1
    57 11.170072225 196.216.192.19 â 52.114.76.76 TCP 66 5061 â 7108 [SYN, ACK] Seq=0 Ack=1 Win=64240 Len=0 MSS=1460 SACK_PERM=1 WS=128
    58 11.333176171 52.114.76.76 â 196.216.192.19 TCP 60 7106 â 5061 [ACK] Seq=8124 Ack=9198 Win=524032 Len=0
    59 11.359073241 52.114.76.76 â 196.216.192.19 TCP 60 7107 â 5061 [ACK] Seq=158 Ack=3054 Win=525568 Len=0
    60 11.363647189 52.114.76.76 â 196.216.192.19 TCP 60 7108 â 5061 [ACK] Seq=1 Ack=1 Win=525568 Len=0

My config includes:

tcp_connection_lifetime=600
tcp_connect_timeout=3000

modparam("proto_tls", "tls_max_msg_chunks", 8)
modparam("tls_mgm", "tls_send_timeout", 2000)
modparam("tls_mgm", "tls_handshake_timeout", 3000)


These are fairly generous time-outs aimed to compensate for slow 
response from Microsoft and the fact that their SIP proxy is on a 
different continent to mine, with approximately 180ms round-trip time in 
latency (typical submarine cable latency from South Africa to Europe).

It doesn't appear to be certificate-related, as the first connection 
verifies the certificates in both directions and connections are to/from 
the same IP addresses. The second and third connections appear to be 
attempts to re-establish a connection after something goes wrong with 
the initial connection.

Microsoft is logging "Server Time-out - TLS misconfiguration on the SBC".

I'm at a bit of a loss as to why the TLS connection - in one direction 
only - is suddenly becoming problematic and why OpenSIPS fails to accept 
re-connections from the same host that, two seconds prior, it was happy 
to accept a connection from.

Any help would be most appreciated!

Thanks

Kind Regards
Greg
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20200707/feb9bba7/attachment-0001.html>

More information about the Users mailing list