Hi, I have a problem creating a TLS connection when tls_method is configured as one of the "loose" methods: SSLv23, TLSv1+, TLSv1.1+, TLSv1.2+. The problem doesn't happen when the tls_method is defined "strictly": TLSv1, TLSv1.1, or TLSv1.2. The problem is reproducible with the modern Yealink phones and also with sipexer. I have Kamailio v.5.5.4 installed from the Kamailio repo ( http://deb.kamailio.org/kamailio55), on Ubuntu 18.04, OpenSSL ver.1.1.1-1ubuntu2.1~18.04.20
The sipexer output: -------------------------- $ ./sipexer -register -vl 3 -co -com -ex 60 -fuser 2001 -cb -au 2001 -ap "......" -sd -sw 20000 -tk ./id_rsa tls:nnnnnnnnn.com:5061
[debug] [sipexer.go:912] main.main(): parsed socket address argument ({Val:tls:nnnnnnnnn.com:5061 Proto:tls Addr:nnnnnnnnn.com Port:5061 PortNo:5061 AType:8 ProtoId:3}) [debug] [sipexer.go:1800] main.SIPExerSendTLS(): client: 192.168.0.178:41586 connected to: 142.93.233.32:5061 [debug] [sipexer.go:1803] main.SIPExerSendTLS(): [48 130 1 34 48 13 6 9 42 134 72 134 247 13 1 1 1 5 0 3 130 1 15 0 48 130 1 10 2 130 1 1 0 222 21 229 237 77 230 193 157 183 132 186 194 65 98 162 250 243 232 189 223 115 181 41 199 130 221 201 143 254 218 254 201 82 173 233 44 158 103 150 78 210 162 187 138 5 179 11 47 208 0 117 27 186 180 197 229 94 13 63 72 227 27 169 127 197 173 67 52 182 68 140 220 132 20 241 57 24 182 29 234 58 60 214 145 225 29 251 240 190 159 43 233 53 57 121 159 81 4 200 12 193 90 91 158 78 196 25 202 74 111 106 215 164 12 178 120 129 8 81 1 245 181 149 20 47 197 165 74 126 24 249 241 187 197 249 209 192 11 204 254 110 19 248 79 122 11 131 24 101 155 237 110 186 5 214 88 79 255 185 156 52 12 29 222 254 76 71 171 142 28 69 22 34 31 111 105 87 7 108 68 6 23 199 236 134 154 42 208 199 158 190 48 193 192 179 120 189 199 117 71 104 231 127 73 128 91 234 168 175 207 55 6 191 144 209 25 10 182 27 53 182 182 96 248 198 206 220 207 102 236 194 96 67 159 34 112 81 145 2 166 207 86 247 232 117 126 158 214 215 10 226 68 81 235 169 81 2 3 1 0 1] <nil> [debug] [sipexer.go:1804] main.SIPExerSendTLS(): CN=nnnnnnnnn.com [debug] [sipexer.go:1803] main.SIPExerSendTLS(): [48 130 2 34....247 31 2 3 1 0 1] <nil> [debug] [sipexer.go:1804] main.SIPExerSendTLS(): CN=ZeroSSL RSA Domain Secure Site CA,O=ZeroSSL,C=AT [debug] [sipexer.go:1803] main.SIPExerSendTLS(): [48 130 2 34 48 ....130 15 2 3 1 0 1] <nil> [debug] [sipexer.go:1804] main.SIPExerSendTLS(): CN=USERTrust RSA Certification Authority,O=The USERTRUST Network,L=Jersey City,ST=New Jersey,C=US [debug] [sipexer.go:1806] main.SIPExerSendTLS(): client: handshake: true [debug] [sipexer.go:1807] main.SIPExerSendTLS(): client: mutual: true [info] [sipexer.go:1432] main.SIPExerDialogLoop(): local socket address: 192.168.0.178:41586 (tls) [info] [sipexer.go:1433] main.SIPExerDialogLoop(): local via address: 192.168.0.178:41586 [info] [sipexer.go:1434] main.SIPExerDialogLoop(): sending to tls 142.xx.yy.32:5061: [[--- REGISTER sip:nnnnnnnnn.com:5061;transport=tls SIP/2.0 Via: SIP/2.0/TLS 192.168.0.178:41586 ;rport;branch=z9hG4bKSG.f7a247eb-5440-4e7a-8a5a-4f849684f30d From: sip:2001@nnnnnnnnn.com;tag=33e66091-193c-4535-b659-d5e562aca5a4 To: sip:2001@nnnnnnnnn.com Call-ID: 4556156d-e8da-4632-82f7-f3ab3c4c73a1 CSeq: 621470 REGISTER Date: Sun, 04 Sep 2022 11:21:33 IDT Contact: sip:192.168.0.178:41586;transport=tls Expires: 60 User-Agent: SIPExer v1.0.2 Content-Length: 0
[info] [sipexer.go:1436] main.SIPExerDialogLoop(): ---]]
[error] [sipexer.go:1312] main.SIPExerDialogReadBytes(): not receiving after 32000ms (bytes 0 - EOF) [debug] [sipexer.go:1009] main.SIPExerExit(): return code: -1154
The Kamailio debug log: --------------------------------- Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/ip_addr.c:577]: print_ip(): tcpconn_new: new tcp connection: 207.232.46.53 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/tcp_main.c:1175]: tcpconn_new(): on port 18566, type 3, socket 72 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/tcp_main.c:1507]: tcpconn_add(): hashes: 1963:2250:2856, 16 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/io_wait.h:375]: io_watch_add(): processing io_watch_add(0x5648d2a55e40, 72, 2, 0x7f9dcaf01958) - fd_no=63 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/io_wait.h:600]: io_watch_del(): DBG: io_watch_del (0x5648d2a55e40, 72, -1, 0x0) fd_no=64 called Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/tcp_main.c:4471]: handle_tcpconn_ev(): sending to child, events 1 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/tcp_main.c:4141]: send2child(): selected tcp worker idx:7 proc:45 pid:25549 for activity on [tls:142.xx.yy.32:5061], 0x7f9dcaf01958 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_read.c:1737]: handle_io(): received n=8 con=0x7f9dcaf01958, fd=10 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:244]: tls_complete_init(): completing tls connection initialization Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:274]: tls_complete_init(): Using initial TLS domain TLSs<default> (dom 0x7f9dc4c17078 ctx 0x7f9dc4c65da0 sn []) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:1208]: tls_lookup_private_key(): Private key lookup for SSL_CTX-0x7f9dc4c65da0: (nil) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:778]: sr_ssl_ctx_info_callback(): SSL handshake started Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:979]: tls_server_name_cb(): received server_name (TLS extension): 'tmx.cpbxmt-demo187.xorcom.com' Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:998]: tls_server_name_cb(): TLS cfg domain selected for received server name [tmx.cpbxmt-demo187.xorcom.com]: socket [:0] server name='' - switching SSL CTX to 0x7f9dc4c65da0 dom 0x7f9dc4c17078 (default) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_main.c:2720]: tcpconn_do_send(): sending... Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_main.c:2753]: tcpconn_do_send(): after real write: c= 0x7f9dcaf01958 n=5435 fd=10 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_main.c:2754]: tcpconn_do_send(): buf= Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: #026#003#003 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/io_wait.h:375]: io_watch_add(): processing io_watch_add(0x5648d29e8c80, 10, 2, 0x7f9dcaf01958) - fd_no=1 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:1208]: tls_lookup_private_key(): Private key lookup for SSL_CTX-0x7f9dc4c65da0: (nil) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:790]: sr_ssl_ctx_info_callback(): SSL handshake done Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:778]: sr_ssl_ctx_info_callback(): SSL handshake started Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:782]: sr_ssl_ctx_info_callback(): SSL renegotiation initiated by client Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:790]: sr_ssl_ctx_info_callback(): SSL handshake done Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:778]: sr_ssl_ctx_info_callback(): SSL handshake started Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:782]: sr_ssl_ctx_info_callback(): SSL renegotiation initiated by client Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:790]: sr_ssl_ctx_info_callback(): SSL handshake done Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:470]: tls_accept(): TLS accept successful Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:477]: tls_accept(): tls_accept: new connection from 207.232.46.53:18566 using TLSv1.3 TLS_AES_256_GCM_SHA384 256 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:480]: tls_accept(): tls_accept: local socket: 142.xx.yy.32:5061 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:491]: tls_accept(): tls_accept: client did not present a certificate Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:1245]: tls_h_read_f(): Reading on a renegotiation of connection (n:-1) (2) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_read.c:1503]: tcp_read_req(): EOF Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/io_wait.h:600]: io_watch_del(): DBG: io_watch_del (0x5648d29e8c80, 10, -1, 0x10) fd_no=2 called Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_read.c:1872]: handle_io(): removing from list 0x7f9dcaf01958 id 16 fd 10, state 2, flags 4018, main fd 72, refcnt 2 ([207.232.46.53]:18566 -> [207.232.46.53]:5061) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_read.c:1656]: release_tcpconn(): releasing con 0x7f9dcaf01958, state -1, fd=10, id=16 ([207.232.46.53]:18566 -> [207.232.46.53]:5061) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_read.c:1660]: release_tcpconn(): extra_data 0x7f9dcaefe628 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/tcp_main.c:3573]: handle_tcp_child(): reader response= 7f9dcaf01958, -1 from 7 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: tls [tls_server.c:729]: tls_h_tcpconn_close_f(): Closing SSL connection 0x7f9dcaefe628
As far as I understood the log, the certificate was accepted but something wrong happened later.
Any suggestion?
Best regards, Leonid Fainshtein
Hi, I'm reposting my request. Any idea how to fix this?
Best regards, Leonid
On Sun, Sep 4, 2022 at 11:53 AM Leonid Fainshtein < leonid.fainshtein@xorcom.com> wrote:
Hi, I have a problem creating a TLS connection when tls_method is configured as one of the "loose" methods: SSLv23, TLSv1+, TLSv1.1+, TLSv1.2+. The problem doesn't happen when the tls_method is defined "strictly": TLSv1, TLSv1.1, or TLSv1.2. The problem is reproducible with the modern Yealink phones and also with sipexer. I have Kamailio v.5.5.4 installed from the Kamailio repo ( http://deb.kamailio.org/kamailio55 https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532186/?link=http%3A%2F%2Fdeb.kamailio.org%2Fkamailio55), on Ubuntu 18.04, OpenSSL ver.1.1.1-1ubuntu2.1~18.04.20
The sipexer output:
$ ./sipexer -register -vl 3 -co -com -ex 60 -fuser 2001 -cb -au 2001 -ap "......" -sd -sw 20000 -tk ./id_rsa tls:nnnnnnnnn.com:5061 https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2Fnnnnnnnnn.com%3A5061
[debug] [sipexer.go:912] main.main(): parsed socket address argument ({Val:tls:nnnnnnnnn.com:5061 https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2Fnnnnnnnnn.com%3A5061 Proto:tls Addr:nnnnnnnnn.com https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2Fnnnnnnnnn.com Port:5061 PortNo:5061 AType:8 ProtoId:3}) [debug] [sipexer.go:1800] main.SIPExerSendTLS(): client: 192.168.0.178:41586 https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2F192.168.0.178%3A41586 connected to: 142.93.233.32:5061 https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2F142.93.233.32%3A5061 [debug] [sipexer.go:1803] main.SIPExerSendTLS(): [48 130 1 34 48 13 6 9 42 134 72 134 247 13 1 1 1 5 0 3 130 1 15 0 48 130 1 10 2 130 1 1 0 222 21 229 237 77 230 193 157 183 132 186 194 65 98 162 250 243 232 189 223 115 181 41 199 130 221 201 143 254 218 254 201 82 173 233 44 158 103 150 78 210 162 187 138 5 179 11 47 208 0 117 27 186 180 197 229 94 13 63 72 227 27 169 127 197 173 67 52 182 68 140 220 132 20 241 57 24 182 29 234 58 60 214 145 225 29 251 240 190 159 43 233 53 57 121 159 81 4 200 12 193 90 91 158 78 196 25 202 74 111 106 215 164 12 178 120 129 8 81 1 245 181 149 20 47 197 165 74 126 24 249 241 187 197 249 209 192 11 204 254 110 19 248 79 122 11 131 24 101 155 237 110 186 5 214 88 79 255 185 156 52 12 29 222 254 76 71 171 142 28 69 22 34 31 111 105 87 7 108 68 6 23 199 236 134 154 42 208 199 158 190 48 193 192 179 120 189 199 117 71 104 231 127 73 128 91 234 168 175 207 55 6 191 144 209 25 10 182 27 53 182 182 96 248 198 206 220 207 102 236 194 96 67 159 34 112 81 145 2 166 207 86 247 232 117 126 158 214 215 10 226 68 81 235 169 81 2 3 1 0 1] <nil> [debug] [sipexer.go:1804] main.SIPExerSendTLS(): CN=nnnnnnnnn.com https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2Fnnnnnnnnn.com [debug] [sipexer.go:1803] main.SIPExerSendTLS(): [48 130 2 34....247 31 2 3 1 0 1] <nil> [debug] [sipexer.go:1804] main.SIPExerSendTLS(): CN=ZeroSSL RSA Domain Secure Site CA,O=ZeroSSL,C=AT [debug] [sipexer.go:1803] main.SIPExerSendTLS(): [48 130 2 34 48 ....130 15 2 3 1 0 1] <nil> [debug] [sipexer.go:1804] main.SIPExerSendTLS(): CN=USERTrust RSA Certification Authority,O=The USERTRUST Network,L=Jersey City,ST=New Jersey,C=US [debug] [sipexer.go:1806] main.SIPExerSendTLS(): client: handshake: true [debug] [sipexer.go:1807] main.SIPExerSendTLS(): client: mutual: true [info] [sipexer.go:1432] main.SIPExerDialogLoop(): local socket address: 192.168.0.178:41586 https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2F192.168.0.178%3A41586 (tls) [info] [sipexer.go:1433] main.SIPExerDialogLoop(): local via address: 192.168.0.178:41586 https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2F192.168.0.178%3A41586 [info] [sipexer.go:1434] main.SIPExerDialogLoop(): sending to tls 142.xx.yy.32:5061: [[--- REGISTER sip:nnnnnnnnn.com:5061;transport=tls SIP/2.0 Via: SIP/2.0/TLS 192.168.0.178:41586 ;rport;branch=z9hG4bKSG.f7a247eb-5440-4e7a-8a5a-4f849684f30d From: sip:2001@nnnnnnnnn.com;tag=33e66091-193c-4535-b659-d5e562aca5a4 To: sip:2001@nnnnnnnnn.com Call-ID: 4556156d-e8da-4632-82f7-f3ab3c4c73a1 CSeq: 621470 REGISTER Date: Sun, 04 Sep 2022 11:21:33 IDT Contact: sip:192.168.0.178:41586;transport=tls Expires: 60 User-Agent: SIPExer v1.0.2 Content-Length: 0
[info] [sipexer.go:1436] main.SIPExerDialogLoop(): ---]]
[error] [sipexer.go:1312] main.SIPExerDialogReadBytes(): not receiving after 32000ms (bytes 0 - EOF) [debug] [sipexer.go:1009] main.SIPExerExit(): return code: -1154
The Kamailio debug log:
Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/ip_addr.c:577]: print_ip(): tcpconn_new: new tcp connection: 207.232.46.53 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/tcp_main.c:1175]: tcpconn_new(): on port 18566, type 3, socket 72 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/tcp_main.c:1507]: tcpconn_add(): hashes: 1963:2250:2856, 16 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/io_wait.h:375]: io_watch_add(): processing io_watch_add(0x5648d2a55e40, 72, 2, 0x7f9dcaf01958) - fd_no=63 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/io_wait.h:600]: io_watch_del(): DBG: io_watch_del (0x5648d2a55e40, 72, -1, 0x0) fd_no=64 called Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/tcp_main.c:4471]: handle_tcpconn_ev(): sending to child, events 1 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/tcp_main.c:4141]: send2child(): selected tcp worker idx:7 proc:45 pid:25549 for activity on [tls:142.xx.yy.32:5061], 0x7f9dcaf01958 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_read.c:1737]: handle_io(): received n=8 con=0x7f9dcaf01958, fd=10 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:244]: tls_complete_init(): completing tls connection initialization Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:274]: tls_complete_init(): Using initial TLS domain TLSs<default> (dom 0x7f9dc4c17078 ctx 0x7f9dc4c65da0 sn []) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:1208]: tls_lookup_private_key(): Private key lookup for SSL_CTX-0x7f9dc4c65da0: (nil) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:778]: sr_ssl_ctx_info_callback(): SSL handshake started Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:979]: tls_server_name_cb(): received server_name (TLS extension): 'tmx.cpbxmt-demo187.xorcom.com https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2Ftmx.cpbxmt-demo187.xorcom.com ' Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:998]: tls_server_name_cb(): TLS cfg domain selected for received server name [tmx.cpbxmt-demo187.xorcom.com https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2Ftmx.cpbxmt-demo187.xorcom.com]: socket [:0] server name='' - switching SSL CTX to 0x7f9dc4c65da0 dom 0x7f9dc4c17078 (default) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_main.c:2720]: tcpconn_do_send(): sending... Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_main.c:2753]: tcpconn_do_send(): after real write: c= 0x7f9dcaf01958 n=5435 fd=10 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_main.c:2754]: tcpconn_do_send(): buf= Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: #026#003#003 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/io_wait.h:375]: io_watch_add(): processing io_watch_add(0x5648d29e8c80, 10, 2, 0x7f9dcaf01958) - fd_no=1 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:1208]: tls_lookup_private_key(): Private key lookup for SSL_CTX-0x7f9dc4c65da0: (nil) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:790]: sr_ssl_ctx_info_callback(): SSL handshake done Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:778]: sr_ssl_ctx_info_callback(): SSL handshake started Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:782]: sr_ssl_ctx_info_callback(): SSL renegotiation initiated by client Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:790]: sr_ssl_ctx_info_callback(): SSL handshake done Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:778]: sr_ssl_ctx_info_callback(): SSL handshake started Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:782]: sr_ssl_ctx_info_callback(): SSL renegotiation initiated by client Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:790]: sr_ssl_ctx_info_callback(): SSL handshake done Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:470]: tls_accept(): TLS accept successful Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:477]: tls_accept(): tls_accept: new connection from 207.232.46.53:18566 https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2F207.232.46.53%3A18566 using TLSv1.3 TLS_AES_256_GCM_SHA384 256 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:480]: tls_accept(): tls_accept: local socket: 142.xx.yy.32:5061 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:491]: tls_accept(): tls_accept: client did not present a certificate Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:1245]: tls_h_read_f(): Reading on a renegotiation of connection (n:-1) (2) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_read.c:1503]: tcp_read_req(): EOF Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/io_wait.h:600]: io_watch_del(): DBG: io_watch_del (0x5648d29e8c80, 10, -1, 0x10) fd_no=2 called Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_read.c:1872]: handle_io(): removing from list 0x7f9dcaf01958 id 16 fd 10, state 2, flags 4018, main fd 72, refcnt 2 ([207.232.46.53]:18566 -> [207.232.46.53]:5061) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_read.c:1656]: release_tcpconn(): releasing con 0x7f9dcaf01958, state -1, fd=10, id=16 ([207.232.46.53]:18566 -> [207.232.46.53]:5061) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_read.c:1660]: release_tcpconn(): extra_data 0x7f9dcaefe628 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/tcp_main.c:3573]: handle_tcp_child(): reader response= 7f9dcaf01958, -1 from 7 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: tls [tls_server.c:729]: tls_h_tcpconn_close_f(): Closing SSL connection 0x7f9dcaefe628
As far as I understood the log, the certificate was accepted but something wrong happened later.
Any suggestion?
Best regards, Leonid Fainshtein
Hello,
as I noticed a debug message about it, likely is the renegotiation, see:
- https://www.kamailio.org/docs/modules/stable/modules/tls.html#tls.p.renegoti...
Cheers, Daniel
On 28.09.22 09:19, Leonid Fainshtein wrote:
Hi, I'm reposting my request. Any idea how to fix this?
Best regards, Leonid
On Sun, Sep 4, 2022 at 11:53 AM Leonid Fainshtein leonid.fainshtein@xorcom.com wrote:
Hi, I have a problem creating a TLS connection when tls_method is configured as one of the "loose" methods: SSLv23, TLSv1+, TLSv1.1+, TLSv1.2+. The problem doesn't happen when the tls_method is defined "strictly": TLSv1, TLSv1.1, or TLSv1.2. The problem is reproducible with the modern Yealink phones and also with sipexer. I have Kamailio v.5.5.4 installed from the Kamailio repo (http://deb.kamailio.org/kamailio55 <https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532186/?link=http%3A%2F%2Fdeb.kamailio.org%2Fkamailio55>), on Ubuntu 18.04, OpenSSL ver.1.1.1-1ubuntu2.1~18.04.20 The sipexer output: -------------------------- $ ./sipexer -register -vl 3 -co -com -ex 60 -fuser 2001 -cb -au 2001 -ap "......" -sd -sw 20000 -tk ./id_rsa tls:nnnnnnnnn.com:5061 <https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2Fnnnnnnnnn.com%3A5061> [debug] [sipexer.go:912] main.main(): parsed socket address argument ({Val:tls:nnnnnnnnn.com:5061 <https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2Fnnnnnnnnn.com%3A5061> Proto:tls Addr:nnnnnnnnn.com <https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2Fnnnnnnnnn.com> Port:5061 PortNo:5061 AType:8 ProtoId:3}) [debug] [sipexer.go:1800] main.SIPExerSendTLS(): client: 192.168.0.178:41586 <https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2F192.168.0.178%3A41586> connected to: 142.93.233.32:5061 <https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2F142.93.233.32%3A5061> [debug] [sipexer.go:1803] main.SIPExerSendTLS(): [48 130 1 34 48 13 6 9 42 134 72 134 247 13 1 1 1 5 0 3 130 1 15 0 48 130 1 10 2 130 1 1 0 222 21 229 237 77 230 193 157 183 132 186 194 65 98 162 250 243 232 189 223 115 181 41 199 130 221 201 143 254 218 254 201 82 173 233 44 158 103 150 78 210 162 187 138 5 179 11 47 208 0 117 27 186 180 197 229 94 13 63 72 227 27 169 127 197 173 67 52 182 68 140 220 132 20 241 57 24 182 29 234 58 60 214 145 225 29 251 240 190 159 43 233 53 57 121 159 81 4 200 12 193 90 91 158 78 196 25 202 74 111 106 215 164 12 178 120 129 8 81 1 245 181 149 20 47 197 165 74 126 24 249 241 187 197 249 209 192 11 204 254 110 19 248 79 122 11 131 24 101 155 237 110 186 5 214 88 79 255 185 156 52 12 29 222 254 76 71 171 142 28 69 22 34 31 111 105 87 7 108 68 6 23 199 236 134 154 42 208 199 158 190 48 193 192 179 120 189 199 117 71 104 231 127 73 128 91 234 168 175 207 55 6 191 144 209 25 10 182 27 53 182 182 96 248 198 206 220 207 102 236 194 96 67 159 34 112 81 145 2 166 207 86 247 232 117 126 158 214 215 10 226 68 81 235 169 81 2 3 1 0 1] <nil> [debug] [sipexer.go:1804] main.SIPExerSendTLS(): CN=nnnnnnnnn.com <https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2Fnnnnnnnnn.com> [debug] [sipexer.go:1803] main.SIPExerSendTLS(): [48 130 2 34....247 31 2 3 1 0 1] <nil> [debug] [sipexer.go:1804] main.SIPExerSendTLS(): CN=ZeroSSL RSA Domain Secure Site CA,O=ZeroSSL,C=AT [debug] [sipexer.go:1803] main.SIPExerSendTLS(): [48 130 2 34 48 ....130 15 2 3 1 0 1] <nil> [debug] [sipexer.go:1804] main.SIPExerSendTLS(): CN=USERTrust RSA Certification Authority,O=The USERTRUST Network,L=Jersey City,ST=New Jersey,C=US [debug] [sipexer.go:1806] main.SIPExerSendTLS(): client: handshake: true [debug] [sipexer.go:1807] main.SIPExerSendTLS(): client: mutual: true [info] [sipexer.go:1432] main.SIPExerDialogLoop(): local socket address: 192.168.0.178:41586 <https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2F192.168.0.178%3A41586> (tls) [info] [sipexer.go:1433] main.SIPExerDialogLoop(): local via address: 192.168.0.178:41586 <https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2F192.168.0.178%3A41586> [info] [sipexer.go:1434] main.SIPExerDialogLoop(): sending to tls 142.xx.yy.32:5061: [[--- REGISTER sip:nnnnnnnnn.com:5061;transport=tls SIP/2.0 Via: SIP/2.0/TLS 192.168.0.178:41586;rport;branch=z9hG4bKSG.f7a247eb-5440-4e7a-8a5a-4f849684f30d From: <sip:2001@nnnnnnnnn.com <mailto:sip%3A2001@nnnnnnnnn.com>>;tag=33e66091-193c-4535-b659-d5e562aca5a4 To: <sip:2001@nnnnnnnnn.com <mailto:sip%3A2001@nnnnnnnnn.com>> Call-ID: 4556156d-e8da-4632-82f7-f3ab3c4c73a1 CSeq: 621470 REGISTER Date: Sun, 04 Sep 2022 11:21:33 IDT Contact: <sip:192.168.0.178:41586;transport=tls> Expires: 60 User-Agent: SIPExer v1.0.2 Content-Length: 0 [info] [sipexer.go:1436] main.SIPExerDialogLoop(): ---]] [error] [sipexer.go:1312] main.SIPExerDialogReadBytes(): not receiving after 32000ms (bytes 0 - EOF) [debug] [sipexer.go:1009] main.SIPExerExit(): return code: -1154 The Kamailio debug log: --------------------------------- Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/ip_addr.c:577]: print_ip(): tcpconn_new: new tcp connection: 207.232.46.53 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/tcp_main.c:1175]: tcpconn_new(): on port 18566, type 3, socket 72 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/tcp_main.c:1507]: tcpconn_add(): hashes: 1963:2250:2856, 16 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/io_wait.h:375]: io_watch_add(): processing io_watch_add(0x5648d2a55e40, 72, 2, 0x7f9dcaf01958) - fd_no=63 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/io_wait.h:600]: io_watch_del(): DBG: io_watch_del (0x5648d2a55e40, 72, -1, 0x0) fd_no=64 called Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/tcp_main.c:4471]: handle_tcpconn_ev(): sending to child, events 1 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/tcp_main.c:4141]: send2child(): selected tcp worker idx:7 proc:45 pid:25549 for activity on [tls:142.xx.yy.32:5061], 0x7f9dcaf01958 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_read.c:1737]: handle_io(): received n=8 con=0x7f9dcaf01958, fd=10 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:244]: tls_complete_init(): completing tls connection initialization Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:274]: tls_complete_init(): Using initial TLS domain TLSs<default> (dom 0x7f9dc4c17078 ctx 0x7f9dc4c65da0 sn []) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:1208]: tls_lookup_private_key(): Private key lookup for SSL_CTX-0x7f9dc4c65da0: (nil) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:778]: sr_ssl_ctx_info_callback(): SSL handshake started Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:979]: tls_server_name_cb(): received server_name (TLS extension): 'tmx.cpbxmt-demo187.xorcom.com <https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2Ftmx.cpbxmt-demo187.xorcom.com>' Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:998]: tls_server_name_cb(): TLS cfg domain selected for received server name [tmx.cpbxmt-demo187.xorcom.com <https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2Ftmx.cpbxmt-demo187.xorcom.com>]: socket [:0] server name='' - switching SSL CTX to 0x7f9dc4c65da0 dom 0x7f9dc4c17078 (default) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_main.c:2720]: tcpconn_do_send(): sending... Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_main.c:2753]: tcpconn_do_send(): after real write: c= 0x7f9dcaf01958 n=5435 fd=10 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_main.c:2754]: tcpconn_do_send(): buf= Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: #026#003#003 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/io_wait.h:375]: io_watch_add(): processing io_watch_add(0x5648d29e8c80, 10, 2, 0x7f9dcaf01958) - fd_no=1 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:1208]: tls_lookup_private_key(): Private key lookup for SSL_CTX-0x7f9dc4c65da0: (nil) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:790]: sr_ssl_ctx_info_callback(): SSL handshake done Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:778]: sr_ssl_ctx_info_callback(): SSL handshake started Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:782]: sr_ssl_ctx_info_callback(): SSL renegotiation initiated by client Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:790]: sr_ssl_ctx_info_callback(): SSL handshake done Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:778]: sr_ssl_ctx_info_callback(): SSL handshake started Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:782]: sr_ssl_ctx_info_callback(): SSL renegotiation initiated by client Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:790]: sr_ssl_ctx_info_callback(): SSL handshake done Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:470]: tls_accept(): TLS accept successful Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:477]: tls_accept(): tls_accept: new connection from 207.232.46.53:18566 <https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2F207.232.46.53%3A18566> using TLSv1.3 TLS_AES_256_GCM_SHA384 256 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:480]: tls_accept(): tls_accept: local socket: 142.xx.yy.32:5061 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:491]: tls_accept(): tls_accept: client did not present a certificate Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:1245]: tls_h_read_f(): Reading on a renegotiation of connection (n:-1) (2) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_read.c:1503]: tcp_read_req(): EOF Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/io_wait.h:600]: io_watch_del(): DBG: io_watch_del (0x5648d29e8c80, 10, -1, 0x10) fd_no=2 called Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_read.c:1872]: handle_io(): removing from list 0x7f9dcaf01958 id 16 fd 10, state 2, flags 4018, main fd 72, refcnt 2 ([207.232.46.53]:18566 -> [207.232.46.53]:5061) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_read.c:1656]: release_tcpconn(): releasing con 0x7f9dcaf01958, state -1, fd=10, id=16 ([207.232.46.53]:18566 -> [207.232.46.53]:5061) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_read.c:1660]: release_tcpconn(): extra_data 0x7f9dcaefe628 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/tcp_main.c:3573]: handle_tcp_child(): reader response= 7f9dcaf01958, -1 from 7 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: tls [tls_server.c:729]: tls_h_tcpconn_close_f(): Closing SSL connection 0x7f9dcaefe628 As far as I understood the log, the certificate was accepted but something wrong happened later. Any suggestion? Best regards, Leonid Fainshtein
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:
Yes, enabling the 'renegotiation' parameter solved the problem.
Thank you very much! Leonid
On Wed, Sep 28, 2022 at 10:45 AM Daniel-Constantin Mierla miconda@gmail.com wrote:
Hello,
as I noticed a debug message about it, likely is the renegotiation, see:
https://www.kamailio.org/docs/modules/stable/modules/tls.html#tls.p.renegoti...
Cheers, Daniel On 28.09.22 09:19, Leonid Fainshtein wrote:
Hi, I'm reposting my request. Any idea how to fix this?
Best regards, Leonid
On Sun, Sep 4, 2022 at 11:53 AM Leonid Fainshtein < leonid.fainshtein@xorcom.com> wrote:
Hi, I have a problem creating a TLS connection when tls_method is configured as one of the "loose" methods: SSLv23, TLSv1+, TLSv1.1+, TLSv1.2+. The problem doesn't happen when the tls_method is defined "strictly": TLSv1, TLSv1.1, or TLSv1.2. The problem is reproducible with the modern Yealink phones and also with sipexer. I have Kamailio v.5.5.4 installed from the Kamailio repo ( http://deb.kamailio.org/kamailio55 https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532186/?link=http%3A%2F%2Fdeb.kamailio.org%2Fkamailio55), on Ubuntu 18.04, OpenSSL ver.1.1.1-1ubuntu2.1~18.04.20
The sipexer output:
$ ./sipexer -register -vl 3 -co -com -ex 60 -fuser 2001 -cb -au 2001 -ap "......" -sd -sw 20000 -tk ./id_rsa tls:nnnnnnnnn.com:5061 https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2Fnnnnnnnnn.com%3A5061
[debug] [sipexer.go:912] main.main(): parsed socket address argument ({Val:tls:nnnnnnnnn.com:5061 https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2Fnnnnnnnnn.com%3A5061 Proto:tls Addr:nnnnnnnnn.com https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2Fnnnnnnnnn.com Port:5061 PortNo:5061 AType:8 ProtoId:3}) [debug] [sipexer.go:1800] main.SIPExerSendTLS(): client: 192.168.0.178:41586 https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2F192.168.0.178%3A41586 connected to: 142.93.233.32:5061 https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2F142.93.233.32%3A5061 [debug] [sipexer.go:1803] main.SIPExerSendTLS(): [48 130 1 34 48 13 6 9 42 134 72 134 247 13 1 1 1 5 0 3 130 1 15 0 48 130 1 10 2 130 1 1 0 222 21 229 237 77 230 193 157 183 132 186 194 65 98 162 250 243 232 189 223 115 181 41 199 130 221 201 143 254 218 254 201 82 173 233 44 158 103 150 78 210 162 187 138 5 179 11 47 208 0 117 27 186 180 197 229 94 13 63 72 227 27 169 127 197 173 67 52 182 68 140 220 132 20 241 57 24 182 29 234 58 60 214 145 225 29 251 240 190 159 43 233 53 57 121 159 81 4 200 12 193 90 91 158 78 196 25 202 74 111 106 215 164 12 178 120 129 8 81 1 245 181 149 20 47 197 165 74 126 24 249 241 187 197 249 209 192 11 204 254 110 19 248 79 122 11 131 24 101 155 237 110 186 5 214 88 79 255 185 156 52 12 29 222 254 76 71 171 142 28 69 22 34 31 111 105 87 7 108 68 6 23 199 236 134 154 42 208 199 158 190 48 193 192 179 120 189 199 117 71 104 231 127 73 128 91 234 168 175 207 55 6 191 144 209 25 10 182 27 53 182 182 96 248 198 206 220 207 102 236 194 96 67 159 34 112 81 145 2 166 207 86 247 232 117 126 158 214 215 10 226 68 81 235 169 81 2 3 1 0 1] <nil> [debug] [sipexer.go:1804] main.SIPExerSendTLS(): CN=nnnnnnnnn.com https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2Fnnnnnnnnn.com [debug] [sipexer.go:1803] main.SIPExerSendTLS(): [48 130 2 34....247 31 2 3 1 0 1] <nil> [debug] [sipexer.go:1804] main.SIPExerSendTLS(): CN=ZeroSSL RSA Domain Secure Site CA,O=ZeroSSL,C=AT [debug] [sipexer.go:1803] main.SIPExerSendTLS(): [48 130 2 34 48 ....130 15 2 3 1 0 1] <nil> [debug] [sipexer.go:1804] main.SIPExerSendTLS(): CN=USERTrust RSA Certification Authority,O=The USERTRUST Network,L=Jersey City,ST=New Jersey,C=US [debug] [sipexer.go:1806] main.SIPExerSendTLS(): client: handshake: true [debug] [sipexer.go:1807] main.SIPExerSendTLS(): client: mutual: true [info] [sipexer.go:1432] main.SIPExerDialogLoop(): local socket address: 192.168.0.178:41586 https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2F192.168.0.178%3A41586 (tls) [info] [sipexer.go:1433] main.SIPExerDialogLoop(): local via address: 192.168.0.178:41586 https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2F192.168.0.178%3A41586 [info] [sipexer.go:1434] main.SIPExerDialogLoop(): sending to tls 142.xx.yy.32:5061: [[--- REGISTER sip:nnnnnnnnn.com:5061;transport=tls SIP/2.0 Via: SIP/2.0/TLS 192.168.0.178:41586 ;rport;branch=z9hG4bKSG.f7a247eb-5440-4e7a-8a5a-4f849684f30d From: sip:2001@nnnnnnnnn.com;tag=33e66091-193c-4535-b659-d5e562aca5a4 To: sip:2001@nnnnnnnnn.com Call-ID: 4556156d-e8da-4632-82f7-f3ab3c4c73a1 CSeq: 621470 REGISTER Date: Sun, 04 Sep 2022 11:21:33 IDT Contact: sip:192.168.0.178:41586;transport=tls Expires: 60 User-Agent: SIPExer v1.0.2 Content-Length: 0
[info] [sipexer.go:1436] main.SIPExerDialogLoop(): ---]]
[error] [sipexer.go:1312] main.SIPExerDialogReadBytes(): not receiving after 32000ms (bytes 0 - EOF) [debug] [sipexer.go:1009] main.SIPExerExit(): return code: -1154
The Kamailio debug log:
Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/ip_addr.c:577]: print_ip(): tcpconn_new: new tcp connection: 207.232.46.53 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/tcp_main.c:1175]: tcpconn_new(): on port 18566, type 3, socket 72 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/tcp_main.c:1507]: tcpconn_add(): hashes: 1963:2250:2856, 16 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/io_wait.h:375]: io_watch_add(): processing io_watch_add(0x5648d2a55e40, 72, 2, 0x7f9dcaf01958) - fd_no=63 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/io_wait.h:600]: io_watch_del(): DBG: io_watch_del (0x5648d2a55e40, 72, -1, 0x0) fd_no=64 called Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/tcp_main.c:4471]: handle_tcpconn_ev(): sending to child, events 1 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/tcp_main.c:4141]: send2child(): selected tcp worker idx:7 proc:45 pid:25549 for activity on [tls:142.xx.yy.32:5061], 0x7f9dcaf01958 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_read.c:1737]: handle_io(): received n=8 con=0x7f9dcaf01958, fd=10 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:244]: tls_complete_init(): completing tls connection initialization Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:274]: tls_complete_init(): Using initial TLS domain TLSs<default> (dom 0x7f9dc4c17078 ctx 0x7f9dc4c65da0 sn []) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:1208]: tls_lookup_private_key(): Private key lookup for SSL_CTX-0x7f9dc4c65da0: (nil) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:778]: sr_ssl_ctx_info_callback(): SSL handshake started Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:979]: tls_server_name_cb(): received server_name (TLS extension): 'tmx.cpbxmt-demo187.xorcom.com https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2Ftmx.cpbxmt-demo187.xorcom.com ' Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:998]: tls_server_name_cb(): TLS cfg domain selected for received server name [tmx.cpbxmt-demo187.xorcom.com https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2Ftmx.cpbxmt-demo187.xorcom.com]: socket [:0] server name='' - switching SSL CTX to 0x7f9dc4c65da0 dom 0x7f9dc4c17078 (default) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_main.c:2720]: tcpconn_do_send(): sending... Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_main.c:2753]: tcpconn_do_send(): after real write: c= 0x7f9dcaf01958 n=5435 fd=10 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_main.c:2754]: tcpconn_do_send(): buf= Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: #026#003#003 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/io_wait.h:375]: io_watch_add(): processing io_watch_add(0x5648d29e8c80, 10, 2, 0x7f9dcaf01958) - fd_no=1 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:1208]: tls_lookup_private_key(): Private key lookup for SSL_CTX-0x7f9dc4c65da0: (nil) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:790]: sr_ssl_ctx_info_callback(): SSL handshake done Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:778]: sr_ssl_ctx_info_callback(): SSL handshake started Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:782]: sr_ssl_ctx_info_callback(): SSL renegotiation initiated by client Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:790]: sr_ssl_ctx_info_callback(): SSL handshake done Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:778]: sr_ssl_ctx_info_callback(): SSL handshake started Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:782]: sr_ssl_ctx_info_callback(): SSL renegotiation initiated by client Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_domain.c:790]: sr_ssl_ctx_info_callback(): SSL handshake done Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:470]: tls_accept(): TLS accept successful Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:477]: tls_accept(): tls_accept: new connection from 207.232.46.53:18566 https://gmlnk.com/api/v1/track/link/click/608535f77fc26b8402a04a3e/1664349532187/?link=http%3A%2F%2F207.232.46.53%3A18566 using TLSv1.3 TLS_AES_256_GCM_SHA384 256 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:480]: tls_accept(): tls_accept: local socket: 142.xx.yy.32:5061 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:491]: tls_accept(): tls_accept: client did not present a certificate Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: tls [tls_server.c:1245]: tls_h_read_f(): Reading on a renegotiation of connection (n:-1) (2) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_read.c:1503]: tcp_read_req(): EOF Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/io_wait.h:600]: io_watch_del(): DBG: io_watch_del (0x5648d29e8c80, 10, -1, 0x10) fd_no=2 called Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_read.c:1872]: handle_io(): removing from list 0x7f9dcaf01958 id 16 fd 10, state 2, flags 4018, main fd 72, refcnt 2 ([207.232.46.53]:18566 -> [207.232.46.53]:5061) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_read.c:1656]: release_tcpconn(): releasing con 0x7f9dcaf01958, state -1, fd=10, id=16 ([207.232.46.53]:18566 -> [207.232.46.53]:5061) Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 45(25549) DEBUG: <core> [core/tcp_read.c:1660]: release_tcpconn(): extra_data 0x7f9dcaefe628 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: <core> [core/tcp_main.c:3573]: handle_tcp_child(): reader response= 7f9dcaf01958, -1 from 7 Sep 4 08:21:33 cpbxmt-demo187 kamailio[23878]: 46(25550) DEBUG: tls [tls_server.c:729]: tls_h_tcpconn_close_f(): Closing SSL connection 0x7f9dcaefe628
As far as I understood the log, the certificate was accepted but something wrong happened later.
Any suggestion?
Best regards, Leonid Fainshtein
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:
-- Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda -- www.linkedin.com/in/miconda Kamailio Advanced Training - Online Nov 7-10, 2022 (Europe Timezone)
-
Daniel-Constantin Mierla -
Leonid Fainshtein