[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:59:58 CEST 2022
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 <miconda at gmail.com>
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 <
> 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
>>
>>
> __________________________________________________________
> 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.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/
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20220928/85a65f47/attachment.htm>
More information about the sr-users
mailing list