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@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