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!
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!
-
Володимир Іванець