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 <[email protected]> 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.renegotiation > > 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 < > [email protected]> 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:[email protected]>;tag=33e66091-193c-4535-b659-d5e562aca5a4 >> To: <sip:[email protected]> >> 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 > * [email protected] > 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 > > -- > Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda -- > www.linkedin.com/in/miconda > Kamailio Advanced Training - Online > Nov 7-10, 2022 (Europe Timezone) > * https://www.asipto.com/sw/kamailio-advanced-training-online/ > >
__________________________________________________________ Kamailio - Users Mailing List - Non Commercial Discussions * [email protected] 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
