Hello,
as I noticed a debug message about it, likely is the renegotiation, see:
-
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(a)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(a)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