[SR-Users] Failed to create a TLS connection when a 'loose' tls_method is configured
Daniel-Constantin Mierla
miconda at gmail.com
Wed Sep 28 09:45:49 CEST 2022
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
> <leonid.fainshtein at 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 at nnnnnnnnn.com
> <mailto:sip%3A2001 at nnnnnnnnn.com>>;tag=33e66091-193c-4535-b659-d5e562aca5a4
> To: <sip:2001 at nnnnnnnnn.com <mailto:sip%3A2001 at 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 at 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
--
Daniel-Constantin Mierla -- www.asipto.com
www.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/
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20220928/7301f47f/attachment.htm>
More information about the sr-users
mailing list