[prev in list] [next in list] [prev in thread] [next in thread]
List: openser-users
Subject: Re: [SR-Users] TLS connection failure. Not sure if system behavior is correct.
From: Володимир Іванець <volodyaivanets () gmail ! c
Date: 2022-05-27 13:48:44
Message-ID: CAOQgkjYRgk9VA5vjU=AjGDrH5bDD2mW2Nr-f_nWCDa3u_aq0ZQ () mail ! gmail ! com
[Download RAW message or body]
[Attachment #2 (multipart/related)]
[Attachment #4 (multipart/alternative)]
Hello all!
Does anyone know why Kamailio might not send ACK to the Change Cipher Spec
request?
Thank you!
пт, 20 трав. 2022 р. о 15:44 Володимир Іванець \
<volodyaivanets@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!
>
[Attachment #7 (text/html)]
<div dir="ltr">Hello all!<br><br>Does anyone know why Kamailio might not send ACK to \
the Change Cipher Spec request?<div><br></div><div>Thank you!</div></div><br><div \
class="gmail_quote"><div dir="ltr" class="gmail_attr">пт, 20 трав. 2022 р. о \
15:44 Володимир Іванець <<a \
href="mailto:volodyaivanets@gmail.com">volodyaivanets@gmail.com</a>> \
пише:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px \
0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr">Hello \
all!<div><br></div><div>My test Kamailio setup (now updated to version 5.5.4) that \
was working with MS Teams some time ago, now stopped :)</div><div>I was wondering if \
someone could tell me if the current behavior is correct or if there is a \
problem?</div><div><br></div><div>Here is a screenshot of the packet \
capture:</div><div><img src="cid:ii_l3efessw0" alt="image.png" width="542" \
height="90"><br></div><div>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?</div><div><br></div><div>There seems to be no issues in the Kamailio debug \
log:</div><blockquote style="margin:0px 0px 0px \
40px;border:none;padding:0px"><div><font face="monospace">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</font></div><div><font face="monospace">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</font></div><div><font \
face="monospace">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</font></div><div><font face="monospace">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:<a \
href="http://172.16.30.206:5062" target="_blank">172.16.30.206:5062</a>], \
0x7fad6a70f6c8</font></div><div><font face="monospace">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</font></div><div><font face="monospace">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)</font></div><div><font face="monospace">May 20 15:29:05 server kamailio[28961]: \
11(28972) DEBUG: <core> [core/tcp_main.c:2720]: tcpconn_do_send(): \
sending...</font></div><div><font face="monospace">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</font></div><div><font face="monospace">May 20 15:29:05 server kamailio[28961]: \
11(28972) DEBUG: <core> [core/tcp_main.c:2754]: tcpconn_do_send(): \
buf=</font></div><div><font face="monospace">May 20 15:29:05 server kamailio[28961]: \
7</font></div></blockquote><blockquote style="margin:0px 0px 0px \
40px;border:none;padding:0px"><div><font face="monospace"><br></font></div><div><font \
face="monospace">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</font></div><div><font face="monospace">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)</font></div><div><font face="monospace">May 20 15:29:05 server kamailio[28961]: \
11(28972) DEBUG: tls [tls_domain.c:790]: sr_ssl_ctx_info_callback(): SSL handshake \
done</font></div><div><font face="monospace">May 20 15:29:05 server kamailio[28961]: \
11(28972) DEBUG: tls [tls_domain.c:794]: sr_ssl_ctx_info_callback(): SSL disable \
renegotiation</font></div><div><font face="monospace">May 20 15:29:05 server \
kamailio[28961]: 11(28972) DEBUG: tls [tls_server.c:542]: tls_connect(): TLS connect \
successful</font></div><div><font face="monospace">May 20 15:29:05 server \
kamailio[28961]: 11(28972) DEBUG: tls [tls_server.c:549]: tls_connect(): tls_connect: \
new connection to <a href="http://52.114.132.46:5061" \
target="_blank">52.114.132.46:5061</a> using TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384 \
256</font></div><div><font face="monospace">May 20 15:29:05 server kamailio[28961]: \
11(28972) DEBUG: tls [tls_server.c:552]: tls_connect(): tls_connect: sending socket: \
<a href="http://172.16.30.206:0" \
target="_blank">172.16.30.206:0</a></font></div><div><font face="monospace">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=<a \
href="http://sip.pstnhub.microsoft.com" \
target="_blank">sip.pstnhub.microsoft.com</a></font></div><div><font \
face="monospace">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</font></div><div><font face="monospace">May 20 15:29:05 server kamailio[28961]: \
11(28972) DEBUG: <core> [core/tcp_main.c:2720]: tcpconn_do_send(): \
sending...</font></div><div><font face="monospace">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</font></div><div><font face="monospace">May 20 15:29:05 server kamailio[28961]: \
11(28972) DEBUG: <core> [core/tcp_main.c:2754]: tcpconn_do_send(): \
buf=</font></div><div><font face="monospace">May 20 15:29:05 server kamailio[28961]: \
▒4▒▒▒▒.▒2T$-▒▒ \
o▒w)▒(▒▒^▒D▒U{xn9▒'</font></div><div><font \
face="monospace">▒&▒t▒▒)▒▒?▒d▒=g▒▒?▒▒▒4/▒▒▒▒-R+▒tR▒H,▒o▒D2r</font></div><div><font \
face="monospace"> \
▒5Q?m▒▒9▒▒#▒O▒▒▒\eϣ▒݄"▒z=▒U▒?</font></div><div><font \
face="monospace">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</font></div><div><font face="monospace">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</font></div><div><font \
face="monospace">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:<a href="http://172.16.30.206:5062" \
target="_blank">172.16.30.206:5062</a>], 0x7fad6a6f25a0</font></div><div><font \
face="monospace">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</font></div><div><font face="monospace">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)</font></div><div><font face="monospace">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)</font></div><div><font face="monospace">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</font></div><div><font face="monospace">May 20 15:29:05 server kamailio[28961]: \
11(28972) DEBUG: <core> [core/tcp_read.c:1503]: tcp_read_req(): \
EOF</font></div><div><font face="monospace">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</font></div><div><font face="monospace">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)</font></div><div><font face="monospace">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)</font></div><div><font \
face="monospace">May 20 15:29:05 server kamailio[28961]: 11(28972) DEBUG: \
<core> [core/tcp_read.c:1660]: release_tcpconn(): extra_data \
0x7fad6a70f008</font></div><div><font face="monospace">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</font></div><div><font \
face="monospace">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</font></div><div><font \
face="monospace"><br></font></div></blockquote><font face="arial, sans-serif">Thank \
you!</font></div> </blockquote></div>
["image.png" (image/png)]
__________________________________________________________
Kamailio - Users Mailing List - Non Commercial Discussions
* sr-users@lists.kamailio.org
Important: keep the mailing list in the recipients, do not reply only to the sender!
Edit mailing list options or unsubscribe:
* https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic