[stunnel-users] Issues after upgrading stunnel to v5.51 on Windows

• Previous message (by thread): [stunnel-users] Stunnel 5.51 Pop3 Problem?
• Next message (by thread): [stunnel-users] stunnel 5.52 released
• Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Hello,

I've been using stunnel v5.50 (x64-pc-mingw32-gnu) to encrypt RTSP traffic between two Win10 Pro computers without any problems.

However, after upgrading to stunnel v5.51 the RTSP traffic has started to stutter (as the framerate has dropped to almost nothing, from 20 fps to 0.01 fps to be precise), and the few frames that are actually transferred arrive visually corrupted.

After enabling debugging at level 7, I get the following (some parts have been obfuscated for privacy reasons):

2019.04.08 00:53:51 LOG7[main]: Found 1 ready file descriptor(s)
2019.04.08 00:53:51 LOG7[main]: FD=528 ifds=r-x ofds=---
2019.04.08 00:53:51 LOG7[main]: FD=536 ifds=r-x ofds=---
2019.04.08 00:53:51 LOG7[main]: FD=544 ifds=r-x ofds=---
2019.04.08 00:53:51 LOG7[main]: FD=648 ifds=r-x ofds=r--
2019.04.08 00:53:51 LOG7[main]: FD=664 ifds=r-x ofds=---
2019.04.08 00:53:51 LOG7[main]: FD=828 ifds=r-x ofds=---
2019.04.08 00:53:51 LOG7[main]: Service [RTSP] accepted (FD=584) from A.B.C.D:E
2019.04.08 00:53:51 LOG7[main]: Creating a new thread
2019.04.08 00:53:51 LOG7[main]: New thread created
2019.04.08 00:53:51 LOG7[2]: Service [RTSP] started
2019.04.08 00:53:51 LOG7[2]: Setting local socket options (FD=584)
2019.04.08 00:53:51 LOG7[2]: Option TCP_NODELAY set on local socket
2019.04.08 00:53:51 LOG5[2]: Service [RTSP] accepted connection from A.B.C.D:E
2019.04.08 00:53:51 LOG6[2]: s_connect: connecting F.G.H.I:J
2019.04.08 00:53:51 LOG7[2]: s_connect: s_poll_wait F.G.H.I:J: waiting 10 seconds
2019.04.08 00:53:51 LOG5[2]: s_connect: connected F.G.H.I:J
2019.04.08 00:53:51 LOG5[2]: Service [RTSP] connected remote server from A.B.C.D:K
2019.04.08 00:53:51 LOG7[2]: Setting remote socket options (FD=900)
2019.04.08 00:53:51 LOG7[2]: Option TCP_NODELAY set on remote socket
2019.04.08 00:53:51 LOG7[2]: Remote descriptor (FD=900) initialized
2019.04.08 00:53:51 LOG6[2]: SNI: sending servername: LLLL
2019.04.08 00:53:51 LOG6[2]: Peer certificate required
2019.04.08 00:53:51 LOG7[2]: TLS state (connect): before SSL initialization
2019.04.08 00:53:51 LOG7[2]: TLS state (connect): SSLv3/TLS write client hello
2019.04.08 00:53:51 LOG7[2]: TLS state (connect): SSLv3/TLS write client hello
2019.04.08 00:53:51 LOG7[2]: TLS state (connect): SSLv3/TLS read server hello
2019.04.08 00:53:51 LOG7[2]: TLS state (connect): TLSv1.3 read encrypted extensions
2019.04.08 00:53:51 LOG7[2]: Verification started at depth=1: O=O, OU=OU, CN=CN
2019.04.08 00:53:51 LOG7[2]: CERT: Pre-verification succeeded
2019.04.08 00:53:51 LOG6[2]: Certificate accepted at depth=1: O=O, OU=OU, CN=CN
2019.04.08 00:53:51 LOG7[2]: Verification started at depth=0: O=O, OU=OU
2019.04.08 00:53:51 LOG7[2]: CERT: Pre-verification succeeded
2019.04.08 00:53:51 LOG6[2]: CERT: Host name "LLLL" matched with "LLLL"
2019.04.08 00:53:51 LOG5[2]: Certificate accepted at depth=0: O=O, OU=OU
2019.04.08 00:53:51 LOG7[2]: TLS state (connect): SSLv3/TLS read server certificate
2019.04.08 00:53:51 LOG7[2]: TLS state (connect): TLSv1.3 read server certificate verify
2019.04.08 00:53:51 LOG7[2]: TLS state (connect): SSLv3/TLS read finished
2019.04.08 00:53:51 LOG7[2]: TLS state (connect): SSLv3/TLS write change cipher spec
2019.04.08 00:53:51 LOG7[2]: TLS state (connect): SSLv3/TLS write finished
2019.04.08 00:53:51 LOG7[2]:      1 client connect(s) requested
2019.04.08 00:53:51 LOG7[2]:      1 client connect(s) succeeded
2019.04.08 00:53:51 LOG7[2]:      0 client renegotiation(s) requested
2019.04.08 00:53:51 LOG7[2]:      0 session reuse(s)
2019.04.08 00:53:51 LOG6[2]: TLS connected: new session negotiated
2019.04.08 00:53:51 LOG6[2]: TLSv1.3 ciphersuite: TLS_CHACHA20_POLY1305_SHA256 (256-bit encryption)
2019.04.08 00:53:51 LOG7[2]: Compression: null, expansion: null
2019.04.08 00:53:51 LOG7[2]: TLS state (connect): SSL negotiation finished successfully
2019.04.08 00:53:51 LOG7[2]: TLS state (connect): SSL negotiation finished successfully
2019.04.08 00:53:51 LOG7[2]: Deallocating application specific data for session connect address
2019.04.08 00:53:51 LOG7[2]: New session callback
2019.04.08 00:53:51 LOG7[2]: Peer certificate was cached (1509 bytes)
2019.04.08 00:53:51 LOG6[2]: Session id: 08B6A892F03C33D29542A794B1C5B0A7646FB9160318EC39D3F294EEF7CAE4EB
2019.04.08 00:53:51 LOG7[2]: TLS state (connect): SSLv3/TLS read server session ticket
2019.04.08 00:53:51 LOG7[2]: TLS state (connect): SSL negotiation finished successfully
2019.04.08 00:53:51 LOG7[2]: TLS state (connect): SSL negotiation finished successfully
2019.04.08 00:53:51 LOG7[2]: New session callback
2019.04.08 00:53:51 LOG7[2]: Deallocating application specific data for session connect address
2019.04.08 00:53:51 LOG6[2]: Session id: 9A06F5437D7039A32E531DA4976EDE9F8CA44820025221D1CE36E237B71E9AD3
2019.04.08 00:53:51 LOG7[2]: TLS state (connect): SSLv3/TLS read server session ticket
2019.04.08 00:54:02 LOG6[2]: Read socket closed (readsocket)
2019.04.08 00:54:02 LOG7[2]: Sending close_notify alert
2019.04.08 00:54:02 LOG7[2]: TLS alert (write): warning: close notify
2019.04.08 00:54:02 LOG6[2]: SSL_shutdown successfully sent close_notify alert
2019.04.08 00:54:02 LOG7[main]: Found 1 ready file descriptor(s)
2019.04.08 00:54:02 LOG7[main]: FD=528 ifds=r-x ofds=---
2019.04.08 00:54:02 LOG7[main]: FD=536 ifds=r-x ofds=---
2019.04.08 00:54:02 LOG7[main]: FD=544 ifds=r-x ofds=---
2019.04.08 00:54:02 LOG7[main]: FD=648 ifds=r-x ofds=r--
2019.04.08 00:54:02 LOG7[main]: FD=664 ifds=r-x ofds=---
2019.04.08 00:54:02 LOG7[main]: FD=828 ifds=r-x ofds=---
2019.04.08 00:54:02 LOG7[main]: Service [RTSP] accepted (FD=908) from A.B.C.D:L
2019.04.08 00:54:02 LOG7[main]: Creating a new thread
2019.04.08 00:54:02 LOG7[main]: New thread created
2019.04.08 00:54:02 LOG7[3]: Service [RTSP] started
2019.04.08 00:54:02 LOG7[3]: Setting local socket options (FD=908)
2019.04.08 00:54:02 LOG7[3]: Option TCP_NODELAY set on local socket
2019.04.08 00:54:02 LOG5[3]: Service [RTSP] accepted connection from A.B.C.D:L
2019.04.08 00:54:02 LOG7[2]: TLS alert (read): warning: close notify
2019.04.08 00:54:02 LOG6[2]: TLS closed (SSL_read)
2019.04.08 00:54:02 LOG7[2]: Sent socket write shutdown
2019.04.08 00:54:02 LOG5[2]: Connection closed: 1374 byte(s) sent to TLS, 1782 byte(s) sent to socket
2019.04.08 00:54:02 LOG7[2]: Remote descriptor (FD=900) closed
2019.04.08 00:54:02 LOG7[2]: Local descriptor (FD=584) closed
2019.04.08 00:54:02 LOG7[2]: Service [RTSP] finished (1 left)
2019.04.08 00:54:02 LOG6[3]: s_connect: connecting F.G.H.I:J
2019.04.08 00:54:02 LOG7[3]: s_connect: s_poll_wait F.G.H.I:J: waiting 10 seconds
2019.04.08 00:54:02 LOG5[3]: s_connect: connected F.G.H.I:J
2019.04.08 00:54:02 LOG5[3]: Service [RTSP] connected remote server from A.B.C.D:M
2019.04.08 00:54:02 LOG7[3]: Setting remote socket options (FD=592)
2019.04.08 00:54:02 LOG7[3]: Option TCP_NODELAY set on remote socket
2019.04.08 00:54:02 LOG7[3]: Remote descriptor (FD=592) initialized
2019.04.08 00:54:02 LOG6[3]: SNI: sending servername: LLLL
2019.04.08 00:54:02 LOG6[3]: Peer certificate required
2019.04.08 00:54:02 LOG7[3]: TLS state (connect): before SSL initialization
2019.04.08 00:54:02 LOG7[3]: TLS state (connect): SSLv3/TLS write client hello
2019.04.08 00:54:02 LOG7[3]: TLS state (connect): SSLv3/TLS write client hello
2019.04.08 00:54:02 LOG7[3]: TLS state (connect): SSLv3/TLS read server hello
2019.04.08 00:54:02 LOG7[3]: TLS state (connect): TLSv1.3 read encrypted extensions
2019.04.08 00:54:02 LOG7[3]: TLS state (connect): SSLv3/TLS read finished
2019.04.08 00:54:02 LOG7[3]: TLS state (connect): SSLv3/TLS write change cipher spec
2019.04.08 00:54:02 LOG7[3]: TLS state (connect): SSLv3/TLS write finished
2019.04.08 00:54:02 LOG7[3]: Remove session callback
2019.04.08 00:54:02 LOG7[3]:      2 client connect(s) requested
2019.04.08 00:54:02 LOG7[3]:      2 client connect(s) succeeded
2019.04.08 00:54:02 LOG7[3]:      0 client renegotiation(s) requested
2019.04.08 00:54:02 LOG7[3]:      1 session reuse(s)
2019.04.08 00:54:02 LOG6[3]: TLS connected: previous session reused
2019.04.08 00:54:02 LOG6[3]: TLSv1.3 ciphersuite: TLS_CHACHA20_POLY1305_SHA256 (256-bit encryption)
2019.04.08 00:54:02 LOG7[3]: Compression: null, expansion: null
2019.04.08 00:54:02 LOG6[3]: Session id: 9A06F5437D7039A32E531DA4976EDE9F8CA44820025221D1CE36E237B71E9AD3
2019.04.08 00:54:02 LOG7[3]: TLS state (connect): SSL negotiation finished successfully
2019.04.08 00:54:02 LOG7[3]: TLS state (connect): SSL negotiation finished successfully
2019.04.08 00:54:02 LOG7[3]: New session callback
2019.04.08 00:54:02 LOG7[3]: Deallocating application specific data for session connect address
2019.04.08 00:54:02 LOG6[3]: Session id: C0F06C6E894812890045433304AD5880C6512D9FD3E61AA67285009143AFD645
2019.04.08 00:54:02 LOG7[3]: TLS state (connect): SSLv3/TLS read server session ticket
2019.04.08 00:54:05 LOG3[3]: transfer() loop executes not transferring any data
2019.04.08 00:54:05 LOG3[3]: please report the problem to Michal.Trojnara at stunnel.org
2019.04.08 00:54:05 LOG3[3]: stunnel 5.51 on x64-pc-mingw32-gnu platform
2019.04.08 00:54:05 LOG3[3]: Compiled/running with OpenSSL 1.1.1b  26 Feb 2019
2019.04.08 00:54:05 LOG3[3]: Threading:WIN32 Sockets:SELECT,IPv6 TLS:ENGINE,OCSP,PSK,SNI
2019.04.08 00:54:05 LOG7[3]: errno: (*_errno())
2019.04.08 00:54:05 LOG3[3]: protocol=TLSv1.3, SSL_pending=0
2019.04.08 00:54:05 LOG3[3]: sock_open_rd=Y, sock_open_wr=Y
2019.04.08 00:54:05 LOG3[3]: SSL_RECEIVED_SHUTDOWN=n, SSL_SENT_SHUTDOWN=n
2019.04.08 00:54:05 LOG3[3]: sock_can_rd=n, sock_can_wr=n
2019.04.08 00:54:05 LOG3[3]: ssl_can_rd=n, ssl_can_wr=n
2019.04.08 00:54:05 LOG3[3]: read_wants_read=Y, read_wants_write=n
2019.04.08 00:54:05 LOG3[3]: write_wants_read=n, write_wants_write=n
2019.04.08 00:54:05 LOG3[3]: shutdown_wants_read=n, shutdown_wants_write=n
2019.04.08 00:54:05 LOG3[3]: socket input buffer: 0 byte(s), TLS input buffer: 0 byte(s)
2019.04.08 00:54:05 LOG5[3]: Connection reset: 1169 byte(s) sent to TLS, 19088 byte(s) sent to socket
2019.04.08 00:54:05 LOG7[3]: Remote descriptor (FD=592) closed
2019.04.08 00:54:05 LOG7[3]: Local descriptor (FD=908) closed
2019.04.08 00:54:05 LOG7[3]: Service [RTSP] finished (0 left)

As you can see, at 00:54:05 there's a log entry that says "transfer() loop executes not transferring any data". Any ideas about why is this happening on v5.51, and how could I solve it?

By the way, should I e-mail this issue to Michal Trojnara as the logs suggests, or should I use this mailing list exclusively?

Thank you,
     Ricardo.-- Best regards

• Previous message (by thread): [stunnel-users] Stunnel 5.51 Pop3 Problem?
• Next message (by thread): [stunnel-users] stunnel 5.52 released
• Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]