Hi,
I'm running stunnel version 5.58 on Windows, everything works perfectly besides that sometimes stunnel gets stuck for 30 seconds - Nothing special in stunnel log, except for the 30 seconds delay:
2020.12.21 14:48:36 LOG6[8]: TLS connected: previous session reused 2020.12.21 14:48:36 LOG6[8]: TLSv1.3 ciphersuite: TLS_AES_256_GCM_SHA384 (256-bit encryption) 2020.12.21 14:48:36 LOG6[8]: Peer temporary key: X25519, 253 bits 2020.12.21 14:48:36 LOG7[8]: Compression: null, expansion: null 2020.12.21 14:48:36 LOG6[8]: Session id: 8E62D0D8EB6359FEA7370E64AA7CC58EF9DB68059A5E01417E7038B773CE60D3 2020.12.21 14:48:36 LOG7[8]: TLS state (connect): SSL negotiation finished successfully 2020.12.21 14:48:36 LOG7[8]: TLS state (connect): SSL negotiation finished successfully 2020.12.21 14:48:36 LOG7[8]: Initializing application specific data for session authenticated 2020.12.21 14:48:36 LOG7[8]: New session callback 2020.12.21 14:48:36 LOG7[8]: Deallocating application specific data for session connect address 2020.12.21 14:48:36 LOG6[8]: Session id: AF8ED185555C6734403C71B514A3F6B75F8484A5AC4EAE6058CFF4D35D929B36 2020.12.21 14:48:36 LOG7[8]: TLS state (connect): SSLv3/TLS read server session ticket 30 sec delay 2020.12.21 14:49:06 LOG6[8]: Read socket closed (readsocket) 2020.12.21 14:49:06 LOG7[8]: Sending close_notify alert 2020.12.21 14:49:06 LOG7[8]: TLS alert (write): warning: close notify 2020.12.21 14:49:06 LOG6[8]: SSL_shutdown successfully sent close_notify alert 2020.12.21 14:49:06 LOG3[8]: transfer: s_poll_wait: TIMEOUTclose exceeded: closing 2020.12.21 14:49:06 LOG7[8]: FD=4540 ifds=--x ofds=--- 2020.12.21 14:49:06 LOG7[8]: FD=4792 ifds=r-x ofds=--- 2020.12.21 14:49:06 LOG5[8]: Connection closed: 64 byte(s) sent to TLS, 0 byte(s) sent to socket 2020.12.21 14:49:06 LOG7[8]: Remote descriptor (FD=4792) closed 2020.12.21 14:49:06 LOG7[8]: Local descriptor (FD=4540) closed 2020.12.21 14:49:06 LOG7[8]: Service [SLNP pem file] finished (0 left) log example when stunnel doesn't get stuck: 2020.12.21 14:49:06 LOG6[9]: TLS connected: previous session reused 2020.12.21 14:49:06 LOG6[9]: TLSv1.3 ciphersuite: TLS_AES_256_GCM_SHA384 (256-bit encryption) 2020.12.21 14:49:06 LOG6[9]: Peer temporary key: X25519, 253 bits 2020.12.21 14:49:06 LOG7[9]: Compression: null, expansion: null 2020.12.21 14:49:06 LOG6[9]: Session id: AF8ED185555C6734403C71B514A3F6B75F8484A5AC4EAE6058CFF4D35D929B36 2020.12.21 14:49:06 LOG7[9]: TLS state (connect): SSL negotiation finished successfully 2020.12.21 14:49:06 LOG7[9]: TLS state (connect): SSL negotiation finished successfully 2020.12.21 14:49:06 LOG7[9]: Initializing application specific data for session authenticated 2020.12.21 14:49:06 LOG7[9]: New session callback 2020.12.21 14:49:06 LOG7[9]: Deallocating application specific data for session connect address 2020.12.21 14:49:06 LOG6[9]: Session id: 44E9010787EFDBC0FCA92724415AD30EF9EDB626D734D894061606C79CD26402 2020.12.21 14:49:06 LOG7[9]: TLS state (connect): SSLv3/TLS read server session ticket 2020.12.21 14:49:06 LOG6[9]: Read socket closed (readsocket) 2020.12.21 14:49:06 LOG7[9]: Sending close_notify alert 2020.12.21 14:49:06 LOG7[9]: TLS alert (write): warning: close notify 2020.12.21 14:49:06 LOG6[9]: SSL_shutdown successfully sent close_notify alert 2020.12.21 14:49:06 LOG3[9]: transfer: s_poll_wait: TIMEOUTclose exceeded: closing 2020.12.21 14:49:06 LOG7[9]: FD=2464 ifds=r-x ofds=--- 2020.12.21 14:49:06 LOG7[9]: FD=2788 ifds=--x ofds=--- 2020.12.21 14:49:06 LOG5[9]: Connection closed: 64 byte(s) sent to TLS, 108 byte(s) sent to socket 2020.12.21 14:49:06 LOG7[9]: Remote descriptor (FD=2464) closed 2020.12.21 14:49:06 LOG7[9]: Local descriptor (FD=2788) closed 2020.12.21 14:49:06 LOG7[9]: Service [SLNP pem file] finished (0 left)
My stunnel conf: debug = 7 output = stunnel.log fips = no options = NO_SSLv2 [SLNP pem file] key = SLNP_urmsand01_new.pem cert = SLNP_urmsand01_new.pem client = yes accept = 8003 connect = host:6443 TIMEOUTbusy = 30 TIMEOUTclose = 0 TIMEOUTconnect = 60 TIMEOUTidle = 86400 With the old stunnel(5.14) it doesn’t happen.
Thanks,
Ditty.
Ditty,
Does this happen a lot? Is it always 30 seconds (exactly)? 30 seconds sounds suspiciously like an IO read timeout. Is the connection with the client a fast and reliable one?
-chris
On 12/21/20 13:09, [email protected] wrote:
Hi,
I'm running stunnel version 5.58 on Windows, everything works perfectly besides that sometimes stunnel gets stuck for 30 seconds - Nothing special in stunnel log, except for the 30 seconds delay:
2020.12.21 14:48:36 LOG6[8]: TLS connected: previous session reused 2020.12.21 14:48:36 LOG6[8]: TLSv1.3 ciphersuite: TLS_AES_256_GCM_SHA384 (256-bit encryption) 2020.12.21 14:48:36 LOG6[8]: Peer temporary key: X25519, 253 bits 2020.12.21 14:48:36 LOG7[8]: Compression: null, expansion: null 2020.12.21 14:48:36 LOG6[8]: Session id: 8E62D0D8EB6359FEA7370E64AA7CC58EF9DB68059A5E01417E7038B773CE60D3 2020.12.21 14:48:36 LOG7[8]: TLS state (connect): SSL negotiation finished successfully 2020.12.21 14:48:36 LOG7[8]: TLS state (connect): SSL negotiation finished successfully 2020.12.21 14:48:36 LOG7[8]: Initializing application specific data for session authenticated 2020.12.21 14:48:36 LOG7[8]: New session callback 2020.12.21 14:48:36 LOG7[8]: Deallocating application specific data for session connect address 2020.12.21 14:48:36 LOG6[8]: Session id: AF8ED185555C6734403C71B514A3F6B75F8484A5AC4EAE6058CFF4D35D929B36 2020.12.21 14:48:36 LOG7[8]: TLS state (connect): SSLv3/TLS read server session ticket 30 sec delay 2020.12.21 14:49:06 LOG6[8]: Read socket closed (readsocket) 2020.12.21 14:49:06 LOG7[8]: Sending close_notify alert 2020.12.21 14:49:06 LOG7[8]: TLS alert (write): warning: close notify 2020.12.21 14:49:06 LOG6[8]: SSL_shutdown successfully sent close_notify alert 2020.12.21 14:49:06 LOG3[8]: transfer: s_poll_wait: TIMEOUTclose exceeded: closing 2020.12.21 14:49:06 LOG7[8]: FD=4540 ifds=--x ofds=--- 2020.12.21 14:49:06 LOG7[8]: FD=4792 ifds=r-x ofds=--- 2020.12.21 14:49:06 LOG5[8]: Connection closed: 64 byte(s) sent to TLS, 0 byte(s) sent to socket 2020.12.21 14:49:06 LOG7[8]: Remote descriptor (FD=4792) closed 2020.12.21 14:49:06 LOG7[8]: Local descriptor (FD=4540) closed 2020.12.21 14:49:06 LOG7[8]: Service [SLNP pem file] finished (0 left) log example when stunnel doesn't get stuck: 2020.12.21 14:49:06 LOG6[9]: TLS connected: previous session reused 2020.12.21 14:49:06 LOG6[9]: TLSv1.3 ciphersuite: TLS_AES_256_GCM_SHA384 (256-bit encryption) 2020.12.21 14:49:06 LOG6[9]: Peer temporary key: X25519, 253 bits 2020.12.21 14:49:06 LOG7[9]: Compression: null, expansion: null 2020.12.21 14:49:06 LOG6[9]: Session id: AF8ED185555C6734403C71B514A3F6B75F8484A5AC4EAE6058CFF4D35D929B36 2020.12.21 14:49:06 LOG7[9]: TLS state (connect): SSL negotiation finished successfully 2020.12.21 14:49:06 LOG7[9]: TLS state (connect): SSL negotiation finished successfully 2020.12.21 14:49:06 LOG7[9]: Initializing application specific data for session authenticated 2020.12.21 14:49:06 LOG7[9]: New session callback 2020.12.21 14:49:06 LOG7[9]: Deallocating application specific data for session connect address 2020.12.21 14:49:06 LOG6[9]: Session id: 44E9010787EFDBC0FCA92724415AD30EF9EDB626D734D894061606C79CD26402 2020.12.21 14:49:06 LOG7[9]: TLS state (connect): SSLv3/TLS read server session ticket 2020.12.21 14:49:06 LOG6[9]: Read socket closed (readsocket) 2020.12.21 14:49:06 LOG7[9]: Sending close_notify alert 2020.12.21 14:49:06 LOG7[9]: TLS alert (write): warning: close notify 2020.12.21 14:49:06 LOG6[9]: SSL_shutdown successfully sent close_notify alert 2020.12.21 14:49:06 LOG3[9]: transfer: s_poll_wait: TIMEOUTclose exceeded: closing 2020.12.21 14:49:06 LOG7[9]: FD=2464 ifds=r-x ofds=--- 2020.12.21 14:49:06 LOG7[9]: FD=2788 ifds=--x ofds=--- 2020.12.21 14:49:06 LOG5[9]: Connection closed: 64 byte(s) sent to TLS, 108 byte(s) sent to socket 2020.12.21 14:49:06 LOG7[9]: Remote descriptor (FD=2464) closed 2020.12.21 14:49:06 LOG7[9]: Local descriptor (FD=2788) closed 2020.12.21 14:49:06 LOG7[9]: Service [SLNP pem file] finished (0 left)
My stunnel conf: debug = 7 output = stunnel.log fips = no options = NO_SSLv2 [SLNP pem file] key = SLNP_urmsand01_new.pem cert = SLNP_urmsand01_new.pem client = yes accept = 8003 connect = host:6443 TIMEOUTbusy = 30 TIMEOUTclose = 0 TIMEOUTconnect = 60 TIMEOUTidle = 86400 With the old stunnel(5.14) it doesn’t happen.
Thanks,
Ditty. _______________________________________________ stunnel-users mailing list -- [email protected] To unsubscribe send an email to [email protected]
HI, thanks for your response!
it happens on average once in every 50 connections it is always *exactly *30 seconds
I tried looking into the servers log and it looks like the session doesn't get to the message received am not familiar with Stunnel but it started happening after upgrading Stunnel from 5.14 to 5.58 ( it happens on 5.57 as well) Ditty
On Tue, Dec 22, 2020 at 6:05 PM Christopher Schultz < [email protected]> wrote:
Ditty,
Does this happen a lot? Is it always 30 seconds (exactly)? 30 seconds sounds suspiciously like an IO read timeout. Is the connection with the client a fast and reliable one?
-chris
On 12/21/20 13:09, [email protected] wrote:
Hi,
I'm running stunnel version 5.58 on Windows, everything works perfectly besides that sometimes stunnel gets stuck for
30 seconds -
Nothing special in stunnel log, except for the 30 seconds delay:
2020.12.21 14:48:36 LOG6[8]: TLS connected: previous session reused 2020.12.21 14:48:36 LOG6[8]: TLSv1.3 ciphersuite: TLS_AES_256_GCM_SHA384
(256-bit encryption)
2020.12.21 14:48:36 LOG6[8]: Peer temporary key: X25519, 253 bits 2020.12.21 14:48:36 LOG7[8]: Compression: null, expansion: null 2020.12.21 14:48:36 LOG6[8]: Session id:
8E62D0D8EB6359FEA7370E64AA7CC58EF9DB68059A5E01417E7038B773CE60D3
2020.12.21 14:48:36 LOG7[8]: TLS state (connect): SSL negotiation
finished successfully
2020.12.21 14:48:36 LOG7[8]: TLS state (connect): SSL negotiation
finished successfully
2020.12.21 14:48:36 LOG7[8]: Initializing application specific data for
session authenticated
2020.12.21 14:48:36 LOG7[8]: New session callback 2020.12.21 14:48:36 LOG7[8]: Deallocating application specific data for
session connect address
2020.12.21 14:48:36 LOG6[8]: Session id:
AF8ED185555C6734403C71B514A3F6B75F8484A5AC4EAE6058CFF4D35D929B36
2020.12.21 14:48:36 LOG7[8]: TLS state (connect): SSLv3/TLS read server
session ticket
30 sec delay 2020.12.21 14:49:06 LOG6[8]: Read socket closed (readsocket) 2020.12.21 14:49:06 LOG7[8]: Sending close_notify alert 2020.12.21 14:49:06 LOG7[8]: TLS alert (write): warning: close notify 2020.12.21 14:49:06 LOG6[8]: SSL_shutdown successfully sent close_notify
alert
2020.12.21 14:49:06 LOG3[8]: transfer: s_poll_wait: TIMEOUTclose
exceeded: closing
2020.12.21 14:49:06 LOG7[8]: FD=4540 ifds=--x ofds=--- 2020.12.21 14:49:06 LOG7[8]: FD=4792 ifds=r-x ofds=--- 2020.12.21 14:49:06 LOG5[8]: Connection closed: 64 byte(s) sent to TLS,
0 byte(s) sent to socket
2020.12.21 14:49:06 LOG7[8]: Remote descriptor (FD=4792) closed 2020.12.21 14:49:06 LOG7[8]: Local descriptor (FD=4540) closed 2020.12.21 14:49:06 LOG7[8]: Service [SLNP pem file] finished (0 left) log example when stunnel doesn't get stuck: 2020.12.21 14:49:06 LOG6[9]: TLS connected: previous session reused 2020.12.21 14:49:06 LOG6[9]: TLSv1.3 ciphersuite: TLS_AES_256_GCM_SHA384
(256-bit encryption)
2020.12.21 14:49:06 LOG6[9]: Peer temporary key: X25519, 253 bits 2020.12.21 14:49:06 LOG7[9]: Compression: null, expansion: null 2020.12.21 14:49:06 LOG6[9]: Session id:
AF8ED185555C6734403C71B514A3F6B75F8484A5AC4EAE6058CFF4D35D929B36
2020.12.21 14:49:06 LOG7[9]: TLS state (connect): SSL negotiation
finished successfully
2020.12.21 14:49:06 LOG7[9]: TLS state (connect): SSL negotiation
finished successfully
2020.12.21 14:49:06 LOG7[9]: Initializing application specific data for
session authenticated
2020.12.21 14:49:06 LOG7[9]: New session callback 2020.12.21 14:49:06 LOG7[9]: Deallocating application specific data for
session connect address
2020.12.21 14:49:06 LOG6[9]: Session id:
44E9010787EFDBC0FCA92724415AD30EF9EDB626D734D894061606C79CD26402
2020.12.21 14:49:06 LOG7[9]: TLS state (connect): SSLv3/TLS read server
session ticket
2020.12.21 14:49:06 LOG6[9]: Read socket closed (readsocket) 2020.12.21 14:49:06 LOG7[9]: Sending close_notify alert 2020.12.21 14:49:06 LOG7[9]: TLS alert (write): warning: close notify 2020.12.21 14:49:06 LOG6[9]: SSL_shutdown successfully sent close_notify
alert
2020.12.21 14:49:06 LOG3[9]: transfer: s_poll_wait: TIMEOUTclose
exceeded: closing
2020.12.21 14:49:06 LOG7[9]: FD=2464 ifds=r-x ofds=--- 2020.12.21 14:49:06 LOG7[9]: FD=2788 ifds=--x ofds=--- 2020.12.21 14:49:06 LOG5[9]: Connection closed: 64 byte(s) sent to TLS,
108 byte(s) sent to socket
2020.12.21 14:49:06 LOG7[9]: Remote descriptor (FD=2464) closed 2020.12.21 14:49:06 LOG7[9]: Local descriptor (FD=2788) closed 2020.12.21 14:49:06 LOG7[9]: Service [SLNP pem file] finished (0 left)
My stunnel conf: debug = 7 output = stunnel.log fips = no options = NO_SSLv2 [SLNP pem file] key = SLNP_urmsand01_new.pem cert = SLNP_urmsand01_new.pem client = yes accept = 8003 connect = host:6443 TIMEOUTbusy = 30 TIMEOUTclose = 0 TIMEOUTconnect = 60 TIMEOUTidle = 86400 With the old stunnel(5.14) it doesn’t happen.
Thanks,
Ditty. _______________________________________________ stunnel-users mailing list -- [email protected] To unsubscribe send an email to [email protected]
stunnel-users mailing list -- [email protected] To unsubscribe send an email to [email protected]
thanks for helping I found this:
https://issues.apache.org/jira/browse/DIRMINA-1132
" While trying to Implement TLSv1.3 in our systems, we found an issue with Mina Core dependency. For TLSv1.2 we never had the issue. But with TLSv1.3, randomly the message sent by the client is discarded. In such scenarios, the server waits for session to pass idle timeout and closes the session"
*Issue:* The actual issue is that the messageReceived() is not being triggered immediately after sending the request. This is happening randomly
adding this line to stunnel conf solved the issue:
sslVersion = TLSv1.2
On Tue, Dec 22, 2020 at 6:24 PM DITTY ADLER [email protected] wrote:
HI, thanks for your response!
it happens on average once in every 50 connections it is always *exactly *30 seconds
I tried looking into the servers log and it looks like the session doesn't get to the message received am not familiar with Stunnel but it started happening after upgrading Stunnel from 5.14 to 5.58 ( it happens on 5.57 as well) Ditty
On Tue, Dec 22, 2020 at 6:05 PM Christopher Schultz < [email protected]> wrote:
Ditty,
Does this happen a lot? Is it always 30 seconds (exactly)? 30 seconds sounds suspiciously like an IO read timeout. Is the connection with the client a fast and reliable one?
-chris
On 12/21/20 13:09, [email protected] wrote:
Hi,
I'm running stunnel version 5.58 on Windows, everything works perfectly besides that sometimes stunnel gets stuck
for 30 seconds -
Nothing special in stunnel log, except for the 30 seconds delay:
2020.12.21 14:48:36 LOG6[8]: TLS connected: previous session reused 2020.12.21 14:48:36 LOG6[8]: TLSv1.3 ciphersuite:
TLS_AES_256_GCM_SHA384 (256-bit encryption)
2020.12.21 14:48:36 LOG6[8]: Peer temporary key: X25519, 253 bits 2020.12.21 14:48:36 LOG7[8]: Compression: null, expansion: null 2020.12.21 14:48:36 LOG6[8]: Session id:
8E62D0D8EB6359FEA7370E64AA7CC58EF9DB68059A5E01417E7038B773CE60D3
2020.12.21 14:48:36 LOG7[8]: TLS state (connect): SSL negotiation
finished successfully
2020.12.21 14:48:36 LOG7[8]: TLS state (connect): SSL negotiation
finished successfully
2020.12.21 14:48:36 LOG7[8]: Initializing application specific data for
session authenticated
2020.12.21 14:48:36 LOG7[8]: New session callback 2020.12.21 14:48:36 LOG7[8]: Deallocating application specific data for
session connect address
2020.12.21 14:48:36 LOG6[8]: Session id:
AF8ED185555C6734403C71B514A3F6B75F8484A5AC4EAE6058CFF4D35D929B36
2020.12.21 14:48:36 LOG7[8]: TLS state (connect): SSLv3/TLS read server
session ticket
30 sec delay 2020.12.21 14:49:06 LOG6[8]: Read socket closed (readsocket) 2020.12.21 14:49:06 LOG7[8]: Sending close_notify alert 2020.12.21 14:49:06 LOG7[8]: TLS alert (write): warning: close notify 2020.12.21 14:49:06 LOG6[8]: SSL_shutdown successfully sent
close_notify alert
2020.12.21 14:49:06 LOG3[8]: transfer: s_poll_wait: TIMEOUTclose
exceeded: closing
2020.12.21 14:49:06 LOG7[8]: FD=4540 ifds=--x ofds=--- 2020.12.21 14:49:06 LOG7[8]: FD=4792 ifds=r-x ofds=--- 2020.12.21 14:49:06 LOG5[8]: Connection closed: 64 byte(s) sent to TLS,
0 byte(s) sent to socket
2020.12.21 14:49:06 LOG7[8]: Remote descriptor (FD=4792) closed 2020.12.21 14:49:06 LOG7[8]: Local descriptor (FD=4540) closed 2020.12.21 14:49:06 LOG7[8]: Service [SLNP pem file] finished (0 left) log example when stunnel doesn't get stuck: 2020.12.21 14:49:06 LOG6[9]: TLS connected: previous session reused 2020.12.21 14:49:06 LOG6[9]: TLSv1.3 ciphersuite:
TLS_AES_256_GCM_SHA384 (256-bit encryption)
2020.12.21 14:49:06 LOG6[9]: Peer temporary key: X25519, 253 bits 2020.12.21 14:49:06 LOG7[9]: Compression: null, expansion: null 2020.12.21 14:49:06 LOG6[9]: Session id:
AF8ED185555C6734403C71B514A3F6B75F8484A5AC4EAE6058CFF4D35D929B36
2020.12.21 14:49:06 LOG7[9]: TLS state (connect): SSL negotiation
finished successfully
2020.12.21 14:49:06 LOG7[9]: TLS state (connect): SSL negotiation
finished successfully
2020.12.21 14:49:06 LOG7[9]: Initializing application specific data for
session authenticated
2020.12.21 14:49:06 LOG7[9]: New session callback 2020.12.21 14:49:06 LOG7[9]: Deallocating application specific data for
session connect address
2020.12.21 14:49:06 LOG6[9]: Session id:
44E9010787EFDBC0FCA92724415AD30EF9EDB626D734D894061606C79CD26402
2020.12.21 14:49:06 LOG7[9]: TLS state (connect): SSLv3/TLS read server
session ticket
2020.12.21 14:49:06 LOG6[9]: Read socket closed (readsocket) 2020.12.21 14:49:06 LOG7[9]: Sending close_notify alert 2020.12.21 14:49:06 LOG7[9]: TLS alert (write): warning: close notify 2020.12.21 14:49:06 LOG6[9]: SSL_shutdown successfully sent
close_notify alert
2020.12.21 14:49:06 LOG3[9]: transfer: s_poll_wait: TIMEOUTclose
exceeded: closing
2020.12.21 14:49:06 LOG7[9]: FD=2464 ifds=r-x ofds=--- 2020.12.21 14:49:06 LOG7[9]: FD=2788 ifds=--x ofds=--- 2020.12.21 14:49:06 LOG5[9]: Connection closed: 64 byte(s) sent to TLS,
108 byte(s) sent to socket
2020.12.21 14:49:06 LOG7[9]: Remote descriptor (FD=2464) closed 2020.12.21 14:49:06 LOG7[9]: Local descriptor (FD=2788) closed 2020.12.21 14:49:06 LOG7[9]: Service [SLNP pem file] finished (0 left)
My stunnel conf: debug = 7 output = stunnel.log fips = no options = NO_SSLv2 [SLNP pem file] key = SLNP_urmsand01_new.pem cert = SLNP_urmsand01_new.pem client = yes accept = 8003 connect = host:6443 TIMEOUTbusy = 30 TIMEOUTclose = 0 TIMEOUTconnect = 60 TIMEOUTidle = 86400 With the old stunnel(5.14) it doesn’t happen.
Thanks,
Ditty. _______________________________________________ stunnel-users mailing list -- [email protected] To unsubscribe send an email to [email protected]
stunnel-users mailing list -- [email protected] To unsubscribe send an email to [email protected]
-
Christopher Schultz -
DITTY ADLER -
dittyadler＠gmail.com