Hi All,
I'm really struggling to make stunnel working for more than a few hours. (and the client is yelling hard...) (I solved some other issue : logging per website and making more than one stunnel works)
To put it in a nutshell :
- stunnel is running and working correctly (I can reach the website in https correctly)
- after some hours I get the following situation :
- stunnel is still running on linux
- trying to connect to a website result in the connection taking very long time and then fails : "The connection to extranet.serviceplus-hse.com was interrupted. Error 101 (net::ERR_CONNECTION_RESET): The connection was reset." (Chrome)
Same symptoms on IE9, Firefox & Lynx (on the server that runs stunnel) (see logs below)
- The following logs are the last one seen in the log file :
- 2012.04.03 23:33:28 LOG5[24792:140152610346752]: Service extranet.serviceplus-hse.com connected remote server from 127.0.0.1:36256
- 2012.04.03 23:33:28 LOG7[24792:140152610346752]: Remote FD=1 initialized
- 2012.04.03 23:33:28 LOG7[24792:140152610346752]: Option TCP_NODELAY set on remote socket
- 2012.04.03 23:33:41 LOG7[24792:140152610346752]: Socket closed on read
- 2012.04.03 23:33:41 LOG7[24792:140152610346752]: Sending SSL write shutdown
- 2012.04.03 23:33:41 LOG7[24792:140152610346752]: SSL alert (write): warning: close notify
- 2012.04.03 23:33:41 LOG6[24792:140152610346752]: SSL_shutdown successfully sent close_notify
- 2012.04.03 23:33:41 LOG3[24792:140152610346752]: transfer: s_poll_wait: TIMEOUTclose exceeded: closing
- 2012.04.03 23:33:41 LOG5[24792:140152610346752]: Connection closed: 186584 bytes sent to SSL, 3275 bytes sent to socket
- 2012.04.03 23:33:41 LOG7[24792:140152610346752]: Service extranet.serviceplus-hse.com finished (0 left)
- 2012.04.04 06:25:04 LOG7[24792:140152610629408]: Dispatching signals from the signal pipe
stopping the firewall & fail2ban do not change anything.
(the last line is logged by this function : static void signal_pipe_empty(void) )
the base stunnel.log has the same ending :
- 2012.04.03 21:10:42 LOG7[24778:139641780209408]: Service https-123monsite.com permitted by libwrap from 212.162.10.34:3244
- 2012.04.03 21:10:42 LOG5[24778:139641780209408]: Service https-123monsite.com accepted connection from 212.162.10.34:3244
- 2012.04.03 21:10:42 LOG7[24778:139641780209408]: SSL state (accept): before/accept initialization
- 2012.04.03 21:10:42 LOG3[24778:139641780209408]: SSL_accept: 1408F10B: error:1408F10B:SSL routines:SSL3_GET_RECORD:wrong version number
- 2012.04.03 21:10:42 LOG5[24778:139641780209408]: Connection reset: 0 bytes sent to SSL, 0 bytes sent to socket
- 2012.04.03 21:10:42 LOG7[24778:139641780209408]: Service https-123monsite.com finished (0 left)
- 2012.04.04 06:25:04 LOG7[24778:139641780213536]: Dispatching signals from the signal pipe
and at the same time (2012.04.04 06:25:04) all logs file stops :
- root@ns0:/var/log/stunnel4# ll
- total 128
- drwxr-xr-x 2 stunnel4 stunnel4 4096 2012-04-04 12:10 .
- drwxr-xr-x 14 root root 4096 2012-04-04 06:25 ..
- -rw-r----- 1 stunnel4 stunnel4 98084 2012-04-04 06:25 extranet.serviceplus-hse.com_stunnel.log
- -rw-r----- 1 stunnel4 stunnel4 4491 2012-04-04 06:25 mansonthomas.com_stunnel.log
- -rw-r----- 1 stunnel4 stunnel4 0 2012-04-04 06:25 stunnel.log
- -rw-r----- 1 stunnel4 stunnel4 11058 2012-04-04 06:25 stunnel.log.1
I've seen some message about the same behavior but after an upgrade on freebsd and didn't find any solution...
- Restarting stunnel restore the service immediately.
below some information about my configuration... ask for more if needed.
Thanks for any helps,
Regards,
Thomas.
Distribution & Pachage info (x64 system)
######################################################################
root@ns0:/var/log/stunnel4# cat /etc/lsb-release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=11.10
DISTRIB_CODENAME=oneiric
DISTRIB_DESCRIPTION="Ubuntu 11.10"
root@ns0:/var/log/stunnel4# aptitude show stunnel4
Package: stunnel4
New: yes
State: installed
Automatically installed: no
Version: 3:4.35-2build1
######################################################################
lynx try :
######################################################################
Retrying connection without TLS.
Alert!: Unable to make secure connection to remote host.
######################################################################
ps -edf :
######################################################################
1 24773 24762 18168 ? -1 S 109 0:00 /usr/bin/stunnel4 /etc/stunnel/base.conf TERM=screen-bce PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/X11R6/bin LANG=en_US.UTF-8 PWD=/
1 24774 24762 18168 ? -1 S 109 0:00 /usr/bin/stunnel4 /etc/stunnel/base.conf TERM=screen-bce PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/X11R6/bin LANG=en_US.UTF-8 PWD=/
1 24775 24762 18168 ? -1 S 109 0:00 /usr/bin/stunnel4 /etc/stunnel/base.conf TERM=screen-bce PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/X11R6/bin LANG=en_US.UTF-8 PWD=/
1 24776 24762 18168 ? -1 S 109 0:00 /usr/bin/stunnel4 /etc/stunnel/base.conf TERM=screen-bce PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/X11R6/bin LANG=en_US.UTF-8 PWD=/
1 24777 24762 18168 ? -1 S 109 0:00 /usr/bin/stunnel4 /etc/stunnel/base.conf TERM=screen-bce PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/X11R6/bin LANG=en_US.UTF-8 PWD=/
1 24778 24778 24778 ? -1 Ss 109 0:00 /usr/bin/stunnel4 /etc/stunnel/base.conf TERM=screen-bce PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/X11R6/bin LANG=en_US.UTF-8 PWD=/
1 24787 24762 18168 ? -1 S 109 0:00 /usr/bin/stunnel4 /etc/stunnel/extranet.serviceplus-hse.com.conf TERM=screen-bce PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/X11R6/bin LANG=en_US.UTF-8 P
1 24788 24762 18168 ? -1 S 109 0:00 /usr/bin/stunnel4 /etc/stunnel/extranet.serviceplus-hse.com.conf TERM=screen-bce PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/X11R6/bin LANG=en_US.UTF-8 P
1 24789 24762 18168 ? -1 S 109 0:00 /usr/bin/stunnel4 /etc/stunnel/extranet.serviceplus-hse.com.conf TERM=screen-bce PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/X11R6/bin LANG=en_US.UTF-8 P
1 24790 24762 18168 ? -1 S 109 0:00 /usr/bin/stunnel4 /etc/stunnel/extranet.serviceplus-hse.com.conf TERM=screen-bce PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/X11R6/bin LANG=en_US.UTF-8 P
1 24791 24762 18168 ? -1 S 109 0:00 /usr/bin/stunnel4 /etc/stunnel/extranet.serviceplus-hse.com.conf TERM=screen-bce PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/X11R6/bin LANG=en_US.UTF-8 P
1 24792 24792 24792 ? -1 Ss 109 0:00 /usr/bin/stunnel4 /etc/stunnel/extranet.serviceplus-hse.com.conf TERM=screen-bce PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/X11R6/bin LANG=en_US.UTF-8 P
1 24801 24762 18168 ? -1 S 109 0:00 /usr/bin/stunnel4 /etc/stunnel/mansonthomas.com.conf TERM=screen-bce PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/X11R6/bin LANG=en_US.UTF-8 PWD=/
1 24802 24762 18168 ? -1 S 109 0:00 /usr/bin/stunnel4 /etc/stunnel/mansonthomas.com.conf TERM=screen-bce PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/X11R6/bin LANG=en_US.UTF-8 PWD=/
1 24803 24762 18168 ? -1 S 109 0:00 /usr/bin/stunnel4 /etc/stunnel/mansonthomas.com.conf TERM=screen-bce PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/X11R6/bin LANG=en_US.UTF-8 PWD=/
1 24804 24762 18168 ? -1 S 109 0:00 /usr/bin/stunnel4 /etc/stunnel/mansonthomas.com.conf TERM=screen-bce PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/X11R6/bin LANG=en_US.UTF-8 PWD=/
1 24805 24762 18168 ? -1 S 109 0:00 /usr/bin/stunnel4 /etc/stunnel/mansonthomas.com.conf TERM=screen-bce PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/X11R6/bin LANG=en_US.UTF-8 PWD=/
1 24806 24806 24806 ? -1 Ss 109 0:00 /usr/bin/stunnel4 /etc/stunnel/mansonthomas.com.conf TERM=screen-bce PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/X11R6/bin LANG=en_US.UTF-8 PWD=/
######################################################################
/etc/stunnel/base.conf
######################################################################
debug = 7
sslVersion = SSLv3
; security enhancements for UNIX systems
; for chroot a copy of some devices and files is needed within the jail
;chroot = /var/lib/stunnel4/
setuid = stunnel4
setgid = stunnel4
; PID is created inside the chroot jail
pid = /var/run/stunnel4/stunnel4.pid
socket = l:TCP_NODELAY=1
socket = r:TCP_NODELAY=1
output = /var/log/stunnel4/stunnel.log
######################################################################
/etc/stunnel/extranet.serviceplus-hse.com.conf
######################################################################
debug = 7
output = /var/log/stunnel4/extranet.serviceplus-hse.com_stunnel.log
setuid = stunnel4
setgid = stunnel4
pid = /var/run/stunnel4/extranet.serviceplus-hse.com.pid
socket = l:TCP_NODELAY=1
socket = r:TCP_NODELAY=1
sslVersion = SSLv3
TIMEOUTclose = 0
######################################################################
Last logs : /var/log/stunnel4/extranet.serviceplus-hse.com_stunnel.log
######################################################################
2012.04.03 23:02:47 LOG6[24792:140152610346752]: SSL accepted: previous session reused
2012.04.03 23:02:47 LOG7[24792:140152610346752]: remote socket: FD=1 allocated (non-blocking mode)
2012.04.03 23:02:47 LOG7[24792:140152610346752]: Remote FD=1 initialized 2012.04.03 23:02:47 LOG7[24792:140152610346752]: Option TCP_NODELAY set on remote socket
2012.04.03 23:02:58 LOG7[24792:140152610346752]: Socket closed on read
2012.04.03 23:02:58 LOG7[24792:140152610346752]: Sending SSL write shutdown 2012.04.03 23:02:58 LOG7[24792:140152610346752]: SSL alert (write): warning: close notify
2012.04.03 23:02:58 LOG6[24792:140152610346752]: SSL_shutdown successfully sent close_notify
2012.04.03 23:02:58 LOG3[24792:140152610346752]: transfer: s_poll_wait: TIMEOUTclose exceeded: closing
2012.04.03 23:02:58 LOG5[24792:140152610346752]: Connection closed: 167313 bytes sent to SSL, 1871 bytes sent to socket
2012.04.03 23:33:20 LOG7[24792:140152610629408]: local socket: FD=0 allocated (non-blocking mode)
2012.04.03 23:33:20 LOG7[24792:140152610346752]: Option TCP_NODELAY set on local socket
2012.04.03 23:33:20 LOG7[24792:140152610346752]: Waiting for a libwrap process 2012.04.03 23:33:20 LOG7[24792:140152610346752]: Acquired libwrap process #0
2012.04.03 23:33:20 LOG7[24792:140152610346752]: Releasing libwrap process #0
2012.04.03 23:33:20 LOG7[24792:140152610346752]: Released libwrap process #0
2012.04.03 23:33:20 LOG7[24792:140152610346752]: SSL state (accept): before/accept initialization
2012.04.03 23:33:20 LOG7[24792:140152610346752]: SSL state (accept): SSLv3 read client hello B
2012.04.03 23:33:20 LOG7[24792:140152610346752]: SSL state (accept): SSLv3 write server hello A
2012.04.03 23:33:20 LOG7[24792:140152610346752]: SSL state (accept): SSLv3 write certificate A
2012.04.03 23:33:20 LOG7[24792:140152610346752]: SSL state (accept): SSLv3 write key exchange A
2012.04.03 23:33:20 LOG7[24792:140152610346752]: SSL state (accept): SSLv3 write server done A
2012.04.03 23:33:20 LOG7[24792:140152610346752]: SSL state (accept): SSLv3 flush data
2012.04.03 23:33:20 LOG7[24792:140152610346752]: SSL state (accept): SSLv3 read client key exchange A
2012.04.03 23:33:20 LOG7[24792:140152610346752]: SSL state (accept): SSLv3 read finished A
2012.04.03 23:33:20 LOG7[24792:140152610346752]: SSL state (accept): SSLv3 write change cipher spec A
2012.04.03 23:33:20 LOG7[24792:140152610346752]: SSL state (accept): SSLv3 write finished A
2012.04.03 23:33:20 LOG7[24792:140152610346752]: SSL state (accept): SSLv3 flush data
2012.04.03 23:33:20 LOG7[24792:140152610346752]: 7 items in the session cache
2012.04.03 23:33:20 LOG7[24792:140152610346752]: 0 client connects (SSL_connect())
2012.04.03 23:33:20 LOG7[24792:140152610346752]: 0 client connects that finished
2012.04.03 23:33:20 LOG7[24792:140152610346752]: 0 client renegotiations requested
2012.04.03 23:33:20 LOG7[24792:140152610346752]: 21 server connects (SSL_accept())
2012.04.03 23:33:20 LOG7[24792:140152610346752]: 20 server connects that finished
2012.04.03 23:33:20 LOG7[24792:140152610346752]: 0 server renegotiations requested
2012.04.03 23:33:20 LOG7[24792:140152610346752]: 9 session cache hits 2012.04.03 23:33:20 LOG7[24792:140152610346752]: 0 external session cache hits
2012.04.03 23:33:20 LOG7[24792:140152610346752]: 7 session cache misses 2012.04.03 23:33:20 LOG7[24792:140152610346752]: 4 session cache timeouts
2012.04.03 23:33:20 LOG6[24792:140152610346752]: SSL accepted: new session negotiated
2012.04.03 23:33:20 LOG6[24792:140152610346752]: Negotiated ciphers: DHE-RSA-CAMELLIA256-SHA SSLv3 Kx=DH Au=RSA Enc=Camellia(256) Mac=SHA1
2012.04.03 23:33:20 LOG7[24792:140152610346752]: remote socket: FD=1 allocated (non-blocking mode)
2012.04.03 23:33:20 LOG7[24792:140152610346752]: Remote FD=1 initialized 2012.04.03 23:33:20 LOG7[24792:140152610346752]: Option TCP_NODELAY set on remote socket
2012.04.03 23:33:27 LOG7[24792:140152610346752]: Socket closed on read
2012.04.03 23:33:27 LOG7[24792:140152610346752]: Sending SSL write shutdown 2012.04.03 23:33:27 LOG7[24792:140152610346752]: SSL alert (write): warning: close notify
2012.04.03 23:33:27 LOG6[24792:140152610346752]: SSL_shutdown successfully sent close_notify
2012.04.03 23:33:27 LOG3[24792:140152610346752]: transfer: s_poll_wait: TIMEOUTclose exceeded: closing
2012.04.03 23:33:27 LOG5[24792:140152610346752]: Connection closed: 537 bytes sent to SSL, 620 bytes sent to socket
2012.04.03 23:33:27 LOG7[24792:140152610629408]: local socket: FD=0 allocated (non-blocking mode)
2012.04.03 23:33:27 LOG7[24792:140152610346752]: Option TCP_NODELAY set on local socket
2012.04.03 23:33:27 LOG7[24792:140152610346752]: Waiting for a libwrap process 2012.04.03 23:33:27 LOG7[24792:140152610346752]: Acquired libwrap process #0
2012.04.03 23:33:27 LOG7[24792:140152610346752]: Releasing libwrap process #0
2012.04.03 23:33:27 LOG7[24792:140152610346752]: Released libwrap process #0
2012.04.03 23:33:27 LOG7[24792:140152610346752]: SSL state (accept): before/accept initialization
2012.04.03 23:33:27 LOG7[24792:140152610346752]: SSL state (accept): SSLv3 read client hello B
2012.04.03 23:33:27 LOG7[24792:140152610346752]: SSL state (accept): SSLv3 write server hello A
2012.04.03 23:33:27 LOG7[24792:140152610346752]: SSL state (accept): SSLv3 write change cipher spec A
2012.04.03 23:33:27 LOG7[24792:140152610346752]: SSL state (accept): SSLv3 write finished A
2012.04.03 23:33:27 LOG7[24792:140152610346752]: SSL state (accept): SSLv3 flush data
2012.04.03 23:33:28 LOG7[24792:140152610346752]: SSL state (accept): SSLv3 read finished A
2012.04.03 23:33:28 LOG7[24792:140152610346752]: 7 items in the session cache
2012.04.03 23:33:28 LOG7[24792:140152610346752]: 0 client connects (SSL_connect())
2012.04.03 23:33:28 LOG7[24792:140152610346752]: 0 client connects that finished
2012.04.03 23:33:28 LOG7[24792:140152610346752]: 0 client renegotiations requested
2012.04.03 23:33:28 LOG7[24792:140152610346752]: 22 server connects (SSL_accept())
2012.04.03 23:33:28 LOG7[24792:140152610346752]: 21 server connects that finished
2012.04.03 23:33:28 LOG7[24792:140152610346752]: 0 server renegotiations requested
2012.04.03 23:33:28 LOG7[24792:140152610346752]: 10 session cache hits
2012.04.03 23:33:28 LOG7[24792:140152610346752]: 0 external session cache hits
2012.04.03 23:33:28 LOG7[24792:140152610346752]: 7 session cache misses 2012.04.03 23:33:28 LOG7[24792:140152610346752]: 4 session cache timeouts
2012.04.03 23:33:28 LOG6[24792:140152610346752]: SSL accepted: previous session reused
2012.04.03 23:33:28 LOG7[24792:140152610346752]: remote socket: FD=1 allocated (non-blocking mode)
2012.04.03 23:33:28 LOG7[24792:140152610346752]: Remote FD=1 initialized 2012.04.03 23:33:28 LOG7[24792:140152610346752]: Option TCP_NODELAY set on remote socket
2012.04.03 23:33:41 LOG7[24792:140152610346752]: Socket closed on read
2012.04.03 23:33:41 LOG7[24792:140152610346752]: Sending SSL write shutdown 2012.04.03 23:33:41 LOG7[24792:140152610346752]: SSL alert (write): warning: close notify
2012.04.03 23:33:41 LOG6[24792:140152610346752]: SSL_shutdown successfully sent close_notify
2012.04.03 23:33:41 LOG3[24792:140152610346752]: transfer: s_poll_wait: TIMEOUTclose exceeded: closing
2012.04.03 23:33:41 LOG5[24792:140152610346752]: Connection closed: 186584 bytes sent to SSL, 3275 bytes sent to socket
2012.04.04 06:25:04 LOG7[24792:140152610629408]: Dispatching signals from the signal pipe
######################################################################