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

Fri May 27 15:48:44 CEST 2022

Hello all!

Does anyone know why Kamailio might not send ACK to  the Change Cipher Spec
request?

Thank you!

пт, 20 трав. 2022 р. о 15:44 Володимир Іванець <volodyaivanets at gmail.com>
пише:

> 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/20220527/373e333d/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/20220527/373e333d/attachment.png>