[SR-Users] TLS connection failure. Not sure if system behavior is correct.

Fri May 20 14:44:28 CEST 2022

Hello all!

My test Kamailio setup (now updated to version 5.5.4) that was working with
MS Teams some time ago, now stopped :)
I was wondering if someone could tell me if the current behavior is correct
or if there is a problem?

Here is a screenshot of the packet capture:
[image: image.png]
I thought that after MS Teams side sent Change Cipher Spec request,
Kamailio should respond with ACK. But instead it just starts sending data
(I believe it sends OPTIONS request. sipdump module captured it). Is this
correct?

There seems to be no issues in the Kamailio debug log:

May 20 15:29:05 server kamailio[28961]: 14(28975) DEBUG: <core>
[core/io_wait.h:782]: io_watch_chg(): DBG: io_watch_chg (0xae9560, 24, 0x1,
0xffffffff) fd_no=20 called
May 20 15:29:05 server kamailio[28961]: 14(28975) DEBUG: <core>
[core/io_wait.h:600]: io_watch_del(): DBG: io_watch_del (0xae9560, 25, -1,
0x0) fd_no=20 called
May 20 15:29:05 server kamailio[28961]: 14(28975) DEBUG: <core>
[core/tcp_main.c:4471]: handle_tcpconn_ev(): sending to child, events 1
May 20 15:29:05 server kamailio[28961]: 14(28975) DEBUG: <core>
[core/tcp_main.c:4144]: send2child(): selected tcp worker idx:1 proc:11
pid:28972 for activity on [tls:172.16.30.206:5062], 0x7fad6a70f6c8
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: <core>
[core/tcp_read.c:1737]: handle_io(): received n=8 con=0x7fad6a70f6c8, fd=6
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: tls
[tls_domain.c:1208]: tls_lookup_private_key(): Private key lookup for
SSL_CTX-0x7fad6a5e1eb8: (nil)
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: <core>
[core/tcp_main.c:2720]: tcpconn_do_send(): sending...
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: <core>
[core/tcp_main.c:2753]: tcpconn_do_send(): after real write: c=
0x7fad6a70f6c8 n=2279 fd=6
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: <core>
[core/tcp_main.c:2754]: tcpconn_do_send(): buf=
May 20 15:29:05 server kamailio[28961]: 7

May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: <core>
[core/io_wait.h:375]: io_watch_add(): processing io_watch_add(0xb555c0, 6,
2, 0x7fad6a70f6c8) - fd_no=1
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: tls
[tls_domain.c:1208]: tls_lookup_private_key(): Private key lookup for
SSL_CTX-0x7fad6a5e1eb8: (nil)
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: tls
[tls_domain.c:790]: sr_ssl_ctx_info_callback(): SSL handshake done
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: tls
[tls_domain.c:794]: sr_ssl_ctx_info_callback(): SSL disable renegotiation
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: tls
[tls_server.c:542]: tls_connect(): TLS connect successful
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: tls
[tls_server.c:549]: tls_connect(): tls_connect: new connection to
52.114.132.46:5061 using TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384 256
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: tls
[tls_server.c:552]: tls_connect(): tls_connect: sending socket:
172.16.30.206:0
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: tls
[tls_server.c:418]: tls_dump_cert_info(): tls_connect: server certificate
subject:/CN=sip.pstnhub.microsoft.com
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: tls
[tls_server.c:422]: tls_dump_cert_info(): tls_connect: server certificate
issuer:/C=US/O=Microsoft Corporation/CN=Microsoft RSA TLS CA 01
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: <core>
[core/tcp_main.c:2720]: tcpconn_do_send(): sending...
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: <core>
[core/tcp_main.c:2753]: tcpconn_do_send(): after real write: c=
0x7fad6a70f6c8 n=509 fd=6
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: <core>
[core/tcp_main.c:2754]: tcpconn_do_send(): buf=
May 20 15:29:05 server kamailio[28961]: ▒4▒▒▒▒.▒2T$-▒▒ o▒w)▒(▒▒^▒D▒U{xn9▒'
▒&▒t▒▒)▒▒?▒d▒=g▒▒?▒▒▒4/▒▒▒▒-R+▒tR▒H,▒o▒D2r
                                          ▒5Q?m▒▒9▒▒#▒O▒▒▒\eϣ▒݄"▒z=▒U▒?
May 20 15:29:05 server kamailio[28961]: 14(28975) DEBUG: <core>
[core/io_wait.h:600]: io_watch_del(): DBG: io_watch_del (0xae9560, 24, -1,
0x0) fd_no=19 called
May 20 15:29:05 server kamailio[28961]: 14(28975) DEBUG: <core>
[core/tcp_main.c:4471]: handle_tcpconn_ev(): sending to child, events 1
May 20 15:29:05 server kamailio[28961]: 14(28975) DEBUG: <core>
[core/tcp_main.c:4144]: send2child(): selected tcp worker idx:2 proc:12
pid:28973 for activity on [tls:172.16.30.206:5062], 0x7fad6a6f25a0
May 20 15:29:05 server kamailio[28961]: 12(28973) DEBUG: <core>
[core/tcp_read.c:1737]: handle_io(): received n=8 con=0x7fad6a6f25a0, fd=6
May 20 15:29:05 server kamailio[28961]: 12(28973) DEBUG: tls
[tls_domain.c:1208]: tls_lookup_private_key(): Private key lookup for
SSL_CTX-0x7fad6a5e1eb8: (nil)
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: <core>
[core/tcp_read.c:304]: tcp_read_data(): EOF on connection 0x7fad6a70f6c8
(state: 0, flags: 18) - FD 6, bytes 0, rd-flags 10000 ([52.114.132.46]:5061
-> [52.114.132.46]:0)11(28972) DEBUG: <coreTCP closed event creation
triggered (reason: 0)
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: <core>
[core/tcp_read.c:192]: tcp_emit_closed_event(): no callback registering for
handling TCP closed event
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: <core>
[core/tcp_read.c:1503]: tcp_read_req(): EOF
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: <core>
[core/io_wait.h:600]: io_watch_del(): DBG: io_watch_del (0xb555c0, 6, -1,
0x10) fd_no=2 called
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: <core>
[core/tcp_read.c:1878]: handle_io(): removing from list 0x7fad6a70f6c8 id 2
fd 6, state 2, flags 18, main fd 25, refcnt 2 ([52.114.132.46]:5061 ->
[52.114.132.46]:0)
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: <core>
[core/tcp_read.c:1659]: release_tcpconn(): releasing con 0x7fad6a70f6c8,
state -1, fd=6, id=2 ([52.114.132.46]:5061 -> [52.114.132.46]:0)
May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: <core>
[core/tcp_read.c:1660]: release_tcpconn(): extra_data 0x7fad6a70f008
May 20 15:29:05 server kamailio[28961]: 14(28975) DEBUG: <core>
[core/tcp_main.c:3574]: handle_tcp_child(): reader response= 7fad6a70f6c8,
-1 from 1
May 20 15:29:05 server kamailio[28961]: 14(28975) DEBUG: tls
[tls_server.c:729]: tls_h_tcpconn_close_f(): Closing SSL connection
0x7fad6a70f008

Thank you!
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20220520/9d10e5b1/attachment.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: image.png
Type: image/png
Size: 50340 bytes
Desc: not available
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20220520/9d10e5b1/attachment.png>