[SR-Users] Failed to create a TLS connection when a 'loose' tls_method is configured

Leonid Fainshtein leonid.fainshtein at xorcom.com
Wed Sep 28 09:19:12 CEST 2022 

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>;tag=33e66091-193c-4535-b659-d5e562aca5a4
> To: <sip:2001 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
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20220928/9ee48deb/attachment.htm>

More information about the sr-users mailing list