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