search

freeswitch / sofia-sip

Sofia-SIP is an open-source SIP User-Agent library, compliant with the IETF RFC3261 specification.
GNU Lesser General Public License v2.1
267 stars 175 forks source link

Incoming TLS connection does not respond to Client Hello on first connection attempt but works on second. #204

Open nvwx opened 1 year ago

nvwx commented 1 year ago

Version 1.12.10devel

When a customer attempts to connect and send an INVITE over a TLS connection, we see the customer SBC send us the Client Hello, but the initial connection attempt is logged as a TCP connection and sofia does not respond and continue the exchange. However, if the customer attempts to make the call again, the subsequent connection works. We've verified certificates are not expired and we can reproduce the issue using openssl.

I have logs below and a pcap I can share privately.

failed call

outside_customer_sbc~$ openssl s_client -connect our.sbc.com:5061 -tls1_2
CONNECTED(00000003)
^C

our side:
2023-02-16 20:17:10.719064 tport.c:2790 tport_wakeup_pri() tport_wakeup_pri(0x560915ea0e60): events IN
2023-02-16 20:17:10.719249 tport.c:880 tport_alloc_secondary() tport_alloc_secondary(0x560915ea0e60): new secondary tport 0x560916191240
2023-02-16 20:17:10.719303 tport_type_tcp.c:203 tport_tcp_init_secondary() tport_tcp_init_secondary(0x560916191240): Setting TCP_KEEPIDLE to 30
2023-02-16 20:17:10.719342 tport_type_tcp.c:209 tport_tcp_init_secondary() tport_tcp_init_secondary(0x560916191240): Setting TCP_KEEPINTVL to 30
2023-02-16 20:17:10.719394 tport.c:2677 tport_accept() tport_accept(0x560916191240): new connection from tcp/outside_customer_sbc:56876
2023-02-16 20:17:10.719432 tport.c:2814 tport_wakeup() tport_wakeup(0x560916191240): events IN
2023-02-16 20:17:10.719464 tport.c:2905 tport_recv_event() tport_recv_event(0x560916191240)
2023-02-16 20:17:10.719503 tport.c:3246 tport_recv_iovec() tport_recv_iovec(0x560916191240) msg 0x5609161ae4a0 from (tcp/outside_customer_sbc:56876) has 221 bytes, veclen = 1
2023-02-16 20:17:10.719564 tport.c:2324 tport_set_secondary_timer() tport(0x560916191240): reset timer
2023-02-16 20:17:18.747205 tport.c:2814 tport_wakeup() tport_wakeup(0x560916191240): events IN
2023-02-16 20:17:18.747471 tport.c:2905 tport_recv_event() tport_recv_event(0x560916191240)
2023-02-16 20:17:18.747528 tport.c:3064 tport_deliver() tport_deliver(0x560916191240): bad msg 0x5609161ae4a0 (0 bytes) from tcp/outside_customer_sbc:56876 next=(nil)
2023-02-16 20:17:18.747568 tport.c:1157 tport_ref() tport_ref(0x560916191240): refcount is now 1
2023-02-16 20:17:18.747605 tport.c:1170 tport_unref() tport_unref(0x560916191240): refcount is now 0
2023-02-16 20:17:18.747637 tport.c:2324 tport_set_secondary_timer() tport(0x560916191240): reset timer
2023-02-16 20:17:18.747669 tport.c:845 tport_set_events() tport_set_events(0x560916191240): events
2023-02-16 20:17:18.747707 tport.c:2185 tport_shutdown0() tport_shutdown0(0x560916191240, 2)
2023-02-16 20:17:18.747810 tport.c:2118 tport_close() tport_close(0x560916191240): tcp/outside_customer_sbc:56876
2023-02-16 20:17:18.747892 tport.c:2291 tport_set_secondary_timer() tport(0x560916191240): set timer at 0 ms because zap

successful call

outside_customer_sbc~$ openssl s_client -connect our.sbc.com:5061 -tls1_2
CONNECTED(00000003)
depth=2 CA stuff...
verify return:1
depth=1  CA stuff...
verify return:1
depth=0 CN = our.sbc.com
verify return:1
[and so on]

2023-02-16 20:17:19.836748 tport.c:2790 tport_wakeup_pri() tport_wakeup_pri(0x560915ea2270): events IN
2023-02-16 20:17:19.836982 tport.c:880 tport_alloc_secondary() tport_alloc_secondary(0x560915ea2270): new secondary tport 0x56091618fbd0
2023-02-16 20:17:19.837081 tport_type_tcp.c:203 tport_tcp_init_secondary() tport_tcp_init_secondary(0x56091618fbd0): Setting TCP_KEEPIDLE to 30
2023-02-16 20:17:19.837118 tport_type_tcp.c:209 tport_tcp_init_secondary() tport_tcp_init_secondary(0x56091618fbd0): Setting TCP_KEEPINTVL to 30
2023-02-16 20:17:19.837231 tport_type_tls.c:618 tport_tls_accept() tport_tls_accept(0x56091618fbd0): new connection from tls/outside_customer_sbc:56962
2023-02-16 20:17:19.837290 tport_tls.c:966 tls_connect() tls_connect(0x56091618fbd0): events NEGOTIATING
2023-02-16 20:17:19.878884 tport_tls.c:966 tls_connect() tls_connect(0x56091618fbd0): events NEGOTIATING
2023-02-16 20:17:19.879299 tport_tls.c:609 tls_post_connection_check() tls_post_connection_check(0x56091618fbd0): TLS cipher chosen (name): ECDHE-RSA-AES256-GCM-SHA384
2023-02-16 20:17:19.879352 tport_tls.c:611 tls_post_connection_check() tls_post_connection_check(0x56091618fbd0): TLS cipher chosen (version): TLSv1.2
2023-02-16 20:17:19.879373 tport_tls.c:614 tls_post_connection_check() tls_post_connection_check(0x56091618fbd0): TLS cipher chosen (bits/alg_bits): 256/256
2023-02-16 20:17:19.879407 tport_tls.c:617 tls_post_connection_check() tls_post_connection_check(0x56091618fbd0): TLS cipher chosen (description): ECDHE-RSA-AES256-GCM-SHA384 TLSv1.2 Kx=ECDH     Au=RSA  Enc=AESGCM(256) Mac=AEAD
2023-02-16 20:17:19.879428 tport_tls.c:622 tls_post_connection_check() tls_post_connection_check(0x56091618fbd0): Peer did not provide X.509 Certificate.
2023-02-16 20:17:19.879461 tport.c:2324 tport_set_secondary_timer() tport(0x56091618fbd0): reset timer
2023-02-16 20:17:20.262603 nta.c:7327 _nta_incoming_timer() nta: timer J fired, terminate 200 response
2023-02-16 20:17:20.262780 nta.c:5994 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7ffef32005c0)
2023-02-16 20:17:20.262842 nta.c:7356 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/5 term, 1/5 free
2023-02-16 20:17:20.262879 nta.c:1367 agent_timer() nta: timer set next to 3531 ms
2023-02-16 20:17:20.821222 tport.c:2814 tport_wakeup() tport_wakeup(0x56091618fbd0): events IN
2023-02-16 20:17:20.821369 tport.c:2185 tport_shutdown0() tport_shutdown0(0x56091618fbd0, 2)
2023-02-16 20:17:20.821394 tport.c:2118 tport_close() tport_close(0x56091618fbd0): tls/outside_customer_sbc:56962
Sivasundareswaran commented 1 year ago

try with TLSv1.3 version

nvwx commented 1 year ago

Hi @Sivasundareswaran, here are the logs when specifying -tls1_3 with s_client.

Edited to provide better example content...

Successful s_client side:

$ openssl s_client -debug -connect sofia:5061 -tls1_3
CONNECTED(00000003)
write to 0x561ee9fa63e0 [0x561ee9fb8320] (248 bytes => 248 (0xF8))
[ content ]
read from 0x561ee9fa63e0 [0x561ee9faf013] (5 bytes => 5 (0x5))
[ more content as handshake completes. ]

Then on the sofia side:

2023-02-27 20:54:15.924922 tport.c:2806 tport_wakeup_pri() tport_wakeup_pri(0x555d194b7a30): events IN
2023-02-27 20:54:15.925081 tport_type_tcp.c:202 tport_tcp_init_secondary() tport_tcp_init_secondary(0x555d19503cb0): Setting TCP_KEEPIDLE to 30
2023-02-27 20:54:15.925114 tport_type_tcp.c:208 tport_tcp_init_secondary() tport_tcp_init_secondary(0x555d19503cb0): Setting TCP_KEEPINTVL to 30
2023-02-27 20:54:15.925182 tport.c:1088 tport_register_secondary() tport_register_secondary(0x555d194b7a30): register secondary tport 0x555d19503cb0 from tls/incoming_IP_address:57776, count(wss) is 0, count(tcp) is 2
2023-02-27 20:54:15.925204 tport_type_tls.c:620 tport_tls_accept() tport_tls_accept(0x555d19503cb0): new connection from tls/incoming_IP_address:57776
2023-02-27 20:54:15.925513 tport_tls.c:970 tls_connect() tls_connect(0x555d19503cb0): events NEGOTIATING
2023-02-27 20:54:15.963909 tport_tls.c:970 tls_connect() tls_connect(0x555d19503cb0): events NEGOTIATING
2023-02-27 20:54:15.964191 tport_tls.c:610 tls_post_connection_check() tls_post_connection_check(0x555d19503cb0): TLS cipher chosen (name): TLS_AES_256_GCM_SHA384
2023-02-27 20:54:15.964232 tport_tls.c:612 tls_post_connection_check() tls_post_connection_check(0x555d19503cb0): TLS cipher chosen (version): TLSv1.3
2023-02-27 20:54:15.964256 tport_tls.c:615 tls_post_connection_check() tls_post_connection_check(0x555d19503cb0): TLS cipher chosen (bits/alg_bits): 256/256
2023-02-27 20:54:15.964292 tport_tls.c:618 tls_post_connection_check() tls_post_connection_check(0x555d19503cb0): TLS cipher chosen (description): TLS_AES_256_GCM_SHA384  TLSv1.3 Kx=any      Au=any  Enc=AESGCM(256) Mac=AEAD
2023-02-27 20:54:15.964315 tport_tls.c:623 tls_post_connection_check() tls_post_connection_check(0x555d19503cb0): Peer did not provide X.509 Certificate.
2023-02-27 20:54:15.964333 tport_tls.c:634 tls_post_connection_check() tls_post_connection_check(0x555d19503cb0): returning X509_V_OK
2023-02-27 20:54:15.964357 tport_tls.c:1043 tls_connect() tls_connect: TLS handshake complete.
2023-02-27 20:54:15.964396 tport.c:2345 tport_set_secondary_timer() tport(0x555d19503cb0): reset timer
2023-02-27 20:54:16.947604 tport.c:2832 tport_wakeup() tport_wakeup(0x555d19503cb0): events IN
2023-02-27 20:54:16.947756 tport.c:2201 tport_shutdown0() tport_shutdown0(0x555d19503cb0, 2) tls/incoming_IP_address:57776
2023-02-27 20:54:16.947786 tport.c:2132 tport_close() tport_close(0x555d19503cb0): tls/incoming_IP_address:57776
2023-02-27 20:54:16.947919 tport.c:2208 tport_shutdown0() tport_shutdown0(0x555d19503cb0): after tport_close refcount is now 0

Failed s_client side:

openssl s_client -debug -connect sofia:5061 -tls1_3
CONNECTED(00000003)
write to 0x5654be97b3e0 [0x5654be98d320] (248 bytes => 248 (0xF8))
[ content ]
^C break after ~7 seconds

sofia side:

2023-02-27 20:54:49.479559 tport.c:2806 tport_wakeup_pri() tport_wakeup_pri(0x555d194b7550): events IN
2023-02-27 20:54:49.479715 tport_type_tcp.c:202 tport_tcp_init_secondary() tport_tcp_init_secondary(0x555d194fdc10): Setting TCP_KEEPIDLE to 30
2023-02-27 20:54:49.479746 tport_type_tcp.c:208 tport_tcp_init_secondary() tport_tcp_init_secondary(0x555d194fdc10): Setting TCP_KEEPINTVL to 30
2023-02-27 20:54:49.479780 tport.c:1088 tport_register_secondary() tport_register_secondary(0x555d194b7550): register secondary tport 0x555d194fdc10 from tcp/incoming_IP_address:40054, count(wss) is 0, count(tcp) is 3
2023-02-27 20:54:49.479809 tport.c:2700 tport_accept() tport_accept(0x555d194fdc10): new connection from tcp/incoming_IP_address:40054
2023-02-27 20:54:49.480563 tport.c:2832 tport_wakeup() tport_wakeup(0x555d194fdc10): events IN
2023-02-27 20:54:49.480627 tport.c:2929 tport_recv_event() tport_recv_event(0x555d194fdc10)
2023-02-27 20:54:49.480662 tport.c:3270 tport_recv_iovec() tport_recv_iovec(0x555d194fdc10) msg 0x555d194fce90 from (tcp/incoming_IP_address:40054) has 248 bytes, veclen = 1
2023-02-27 20:54:49.480699 tport.c:2345 tport_set_secondary_timer() tport(0x555d194fdc10): reset timer

<break on s_client side>

2023-02-27 20:54:57.762442 tport.c:2832 tport_wakeup() tport_wakeup(0x555d194fdc10): events IN
2023-02-27 20:54:57.762585 tport.c:2929 tport_recv_event() tport_recv_event(0x555d194fdc10)
2023-02-27 20:54:57.762625 tport.c:3088 tport_deliver() tport_deliver(0x555d194fdc10): bad msg 0x555d194fce90 (0 bytes) from tcp/incoming_IP_address:40054 next=(nil)
2023-02-27 20:54:57.762645 tport.c:1171 tport_ref() tport_ref(0x555d194fdc10): refcount is now 1
2023-02-27 20:54:57.762666 tport.c:1184 tport_unref() tport_unref(0x555d194fdc10): refcount is now 0
2023-02-27 20:54:57.762686 tport.c:2345 tport_set_secondary_timer() tport(0x555d194fdc10): reset timer
2023-02-27 20:54:57.762712 tport.c:852 tport_set_events() tport_set_events(0x555d194fdc10): events
2023-02-27 20:54:57.762733 tport.c:2965 tport_recv_event() tport_recv_event(0x555d194fdc10): end of stream from tcp/incoming_IP_address:40054 refcount is 0
2023-02-27 20:54:57.762751 tport.c:2201 tport_shutdown0() tport_shutdown0(0x555d194fdc10, 2) tcp/incoming_IP_address:40054
2023-02-27 20:54:57.762769 tport.c:2132 tport_close() tport_close(0x555d194fdc10): tcp/incoming_IP_address:40054
2023-02-27 20:54:57.762816 tport.c:2208 tport_shutdown0() tport_shutdown0(0x555d194fdc10): after tport_close refcount is now 0
2023-02-27 20:54:57.762841 tport.c:2971 tport_recv_event() tport_recv_event(0x555d194fdc10): back from tport_shutdown0 refcount is now 0
2023-02-27 20:54:57.762859 tport.c:2311 tport_set_secondary_timer() tport(0x555d194fdc10): set timer at 0 ms because zap
2023-02-27 20:54:57.762884 tport.c:1155 tport_zap_secondary() tport_zap_secondary(0x555d194b7550): zap tport 0x555d194fdc10 from tcp/incoming_IP_address:40054, count(wss) is 0, count(tcp) is 2
Sivasundareswaran commented 1 year ago

Please check the openssl version of both client and server ,if both are different use same version