[stunnel-users] Odd termination of stunnel process...

Robert Nickel rnickel+stunnel at scea.com
Mon May 4 23:15:35 CEST 2009 

We've been happily using stunnel for quite some time now and have run into a
strange problem.  At seemingly random intervals, stunnel just freaks out an
dies.  I don't know if it's getting overwhelmed or what but I'm not seeing
anything in the logs for stunnel or any other process.  Any help is
appreciated.

Stunnel is being used to wrap a service that was written without use of the
ssl libraries directly and connects to two remote web servers (that happen to
be running on the same host, separate ports).

Config information:
  OS:         CentOS 5.1
  OpenSSL:    0.9.8b
  stunnel -version:
      stunnel 4.15 on i686-redhat-linux-gnu with OpenSSL 0.9.8b 04 May 2006
      Threading:PTHREAD SSL:ENGINE Sockets:POLL,IPv6 Auth:LIBWRAP
       
       Global options
       debug           = 5
       pid             = /var/run/stunnel.pid
       RNDbytes        = 64
       RNDfile         = /dev/urandom
       RNDoverwrite    = yes
        
        Service-level options
        cert            = /etc/stunnel/stunnel.pem
        ciphers         = ALL:!ADH:+RC4:@STRENGTH
        key             = /etc/stunnel/stunnel.pem
        session         = 300 seconds
        TIMEOUTbusy     = 300 seconds
        TIMEOUTclose    = 60 seconds
        TIMEOUTconnect  = 10 seconds
        TIMEOUTidle     = 43200 seconds
        verify          = none
    Config file contents:
      client=yes
      foreground=no
      pid=/var/run/pid
      chroot=/path/to/chroot
      setuid=non-priv-user
      setgid=non-priv-group
      [webservice1]
      accept=127.0.0.1:11000
      connect=172.16.0.1:11000
      [webservice2]
      accept=127.0.0.1:11001
      connect=172.16.0.1:11001

Below are the log lines just before the process disappears:
  
May  4 19:49:18 host stunnel: LOG7[28683:3085368208]: Remote FD=15 initialized
May  4 19:49:18 host stunnel: LOG7[28683:3085298576]: SSL state (connect): SSLv3 write client key exchange A
May  4 19:49:18 host stunnel: LOG7[28683:3085298576]: SSL state (connect): SSLv3 write change cipher spec A
May  4 19:49:18 host stunnel: LOG7[28683:3085298576]: SSL state (connect): SSLv3 write finished A
May  4 19:49:18 host stunnel: LOG7[28683:3085716368]: SSL state (connect): SSLv3 read server hello A
May  4 19:49:18 host stunnel: LOG7[28683:3085716368]: SSL state (connect): SSLv3 read server certificate A
May  4 19:49:18 host stunnel: LOG7[28683:3085298576]: SSL state (connect): SSLv3 flush data
May  4 19:49:18 host stunnel: LOG7[28683:3085368208]: SSL state (connect): before/connect initialization
May  4 19:49:18 host stunnel: LOG7[28683:3085786000]: SSL alert (write): fatal: handshake failure
May  4 19:49:18 host stunnel: LOG3[28683:3085786000]: SSL_connect: 1408C095: error:1408C095:SSL routines:SSL3_GET_FINISHED:digest check failed
May  4 19:49:18 host stunnel: LOG5[28683:3085786000]: Connection reset: 0 bytes sent to SSL, 0 bytes sent to socket
May  4 19:49:18 host stunnel: LOG7[28683:3085786000]: replay finished (8 left)
May  4 19:49:18 host stunnel: LOG7[28683:3085368208]: SSL state (connect): SSLv3 write client hello A
May  4 19:49:18 host stunnel: LOG7[28683:3085716368]: SSL state (connect): SSLv3 read server key exchange A
May  4 19:49:18 host stunnel: LOG7[28683:3085716368]: SSL state (connect): SSLv3 read server done A
May  4 19:49:18 host stunnel: LOG7[28683:3085928144]: replay accepted FD=18 from 127.0.0.1:40308
May  4 19:49:18 host stunnel: LOG7[28683:3085786000]: replay started
May  4 19:49:18 host stunnel: LOG7[28683:3085786000]: FD 18 in non-blocking mode
May  4 19:49:18 host stunnel: LOG7[28683:3085786000]: FD 19 in non-blocking mode
May  4 19:49:18 host stunnel: LOG7[28683:3085786000]: FD 26 in non-blocking mode
May  4 19:49:18 host stunnel: LOG7[28683:3085786000]: Connection from 127.0.0.1:40308 permitted by libwrap
May  4 19:49:18 host stunnel: LOG5[28683:3085786000]: replay connected from 127.0.0.1:40308
May  4 19:49:18 host stunnel: LOG7[28683:3085786000]: FD 19 in non-blocking mode
May  4 19:49:18 host stunnel: LOG7[28683:3085786000]: replay connecting 160.33.167.33:11026
May  4 19:49:18 host stunnel: LOG7[28683:3085786000]: connect_wait: waiting 10 seconds
May  4 19:49:18 host stunnel: LOG7[28683:3085928144]: Cleaning up the signal pipe
May  4 19:49:18 host stunnel: LOG6[28683:3085928144]: Child process 13775 finished with code 0
May  4 19:49:18 host stunnel: LOG7[28683:3085646736]: SSL alert (write): fatal: handshake failure
May  4 19:49:18 host stunnel: LOG3[28683:3085646736]: SSL_connect: 1408C095: error:1408C095:SSL routines:SSL3_GET_FINISHED:digest check failed
May  4 19:49:18 host stunnel: LOG5[28683:3085646736]: Connection reset: 0 bytes sent to SSL, 0 bytes sent to socket
May  4 19:49:18 host stunnel: LOG7[28683:3085716368]: SSL state (connect): SSLv3 write client key exchange A
May  4 19:49:18 host stunnel: LOG7[28683:3085716368]: SSL state (connect): SSLv3 write change cipher spec A
May  4 19:49:18 host stunnel: LOG7[28683:3085716368]: SSL state (connect): SSLv3 write finished A
May  4 19:49:18 host stunnel: LOG7[28683:3085716368]: SSL state (connect): SSLv3 flush data
May  4 19:49:18 host stunnel: LOG7[28683:3085646736]: replay finished (8 left)
May  4 19:49:18 host stunnel: LOG7[28683:3085855632]: connect_wait: connected
May  4 19:49:18 host stunnel: LOG7[28683:3085855632]: Remote FD=17 initialized
May  4 19:49:18 host stunnel: LOG7[28683:3085855632]: SSL state (connect): before/connect initialization
May  4 19:49:18 host stunnel: LOG7[28683:3085855632]: SSL state (connect): SSLv3 write client hello A
May  4 19:49:18 host stunnel: LOG7[28683:3085928144]: replay accepted FD=22 from 127.0.0.1:40310
May  4 19:49:18 host stunnel: LOG7[28683:3085646736]: replay started
May  4 19:49:18 host stunnel: LOG7[28683:3085646736]: FD 22 in non-blocking mode
May  4 19:49:18 host stunnel: LOG7[28683:3085646736]: FD 23 in non-blocking mode
May  4 19:49:18 host stunnel: LOG7[28683:3085646736]: FD 26 in non-blocking mode
May  4 19:49:18 host stunnel: LOG7[28683:3085928144]: Cleaning up the signal pipe
May  4 19:49:18 host stunnel: LOG6[28683:3085928144]: Child process 13777 finished with code 0
May  4 19:49:18 host stunnel: LOG7[28683:3085646736]: Connection from 127.0.0.1:40310 permitted by libwrap
May  4 19:49:18 host stunnel: LOG5[28683:3085646736]: replay connected from 127.0.0.1:40310
May  4 19:49:18 host stunnel: LOG7[28683:3085646736]: FD 23 in non-blocking mode
May  4 19:49:18 host stunnel: LOG7[28683:3085646736]: replay connecting 160.33.167.33:11026
May  4 19:49:18 host stunnel: LOG7[28683:3085646736]: connect_wait: waiting 10 seconds
May  4 19:49:18 host stunnel: LOG7[28683:3085507472]: SSL state (connect): SSLv3 read server hello A
May  4 19:49:18 host stunnel: LOG7[28683:3085507472]: SSL state (connect): SSLv3 read server certificate A
May  4 19:49:18 host stunnel: LOG7[28683:3085507472]: SSL state (connect): SSLv3 read server key exchange A
May  4 19:49:18 host stunnel: LOG7[28683:3085507472]: SSL state (connect): SSLv3 read server done A
May  4 19:49:18 host stunnel: LOG7[28683:3085786000]: connect_wait: connected
May  4 19:49:18 host stunnel: LOG7[28683:3085786000]: Remote FD=19 initialized
May  4 19:49:18 host stunnel: LOG7[28683:3085786000]: SSL state (connect): before/connect initialization
May  4 19:49:18 host stunnel: LOG7[28683:3085786000]: SSL state (connect): SSLv3 write client hello A
May  4 19:49:18 host stunnel: LOG7[28683:3085298576]: SSL alert (write): fatal: handshake failure
May  4 19:49:18 host stunnel: LOG3[28683:3085298576]: SSL_connect: 1408C095: error:1408C095:SSL routines:SSL3_GET_FINISHED:digest check failed
May  4 19:49:18 host stunnel: LOG5[28683:3085298576]: Connection reset: 0 bytes sent to SSL, 0 bytes sent to socket
May  4 19:49:18 host stunnel: LOG7[28683:3085298576]: replay finished (8 left)
May  4 19:49:18 host stunnel: LOG7[28683:3085507472]: SSL state (connect): SSLv3 write client key exchange A
May  4 19:49:18 host stunnel: LOG7[28683:3085507472]: SSL state (connect): SSLv3 write change cipher spec A
May  4 19:49:18 host stunnel: LOG7[28683:3085507472]: SSL state (connect): SSLv3 write finished A
May  4 19:49:18 host stunnel: LOG7[28683:3085507472]: SSL state (connect): SSLv3 flush data
May  4 19:49:18 host stunnel: LOG7[28683:3085925264]: SSL alert (write): fatal: handshake failure
May  4 19:49:18 host stunnel: LOG3[28683:3085925264]: SSL_connect: 1408C095: error:1408C095:SSL routines:SSL3_GET_FINISHED:digest check failed
May  4 19:49:18 host stunnel: LOG5[28683:3085925264]: Connection reset: 0 bytes sent to SSL, 0 bytes sent to socket
May  4 19:49:18 host stunnel: LOG7[28683:3085925264]: replay finished (7 left)
May  4 19:49:18 host stunnel: LOG7[28683:3085368208]: SSL state (connect): SSLv3 read server hello A
May  4 19:49:18 host stunnel: LOG7[28683:3085368208]: SSL state (connect): SSLv3 read server certificate A
May  4 19:49:18 host stunnel: LOG7[28683:3085368208]: SSL state (connect): SSLv3 read server key exchange A
May  4 19:49:18 host stunnel: LOG7[28683:3085368208]: SSL state (connect): SSLv3 read server done A
May  4 19:49:18 host stunnel: LOG7[28683:3085577104]: SSL state (connect): SSLv3 read server hello A
May  4 19:49:18 host stunnel: LOG7[28683:3085577104]: SSL state (connect): SSLv3 read server certificate A
May  4 19:49:18 host stunnel: LOG7[28683:3085577104]: SSL state (connect): SSLv3 read server key exchange A
May  4 19:49:18 host stunnel: LOG7[28683:3085577104]: SSL state (connect): SSLv3 read server done A
[stunnel vanishes at this point.  No core, no logs.  POOF!]

The lines that stand out to me are the SSL_connect digest errors, the finished
lines (showing the number of queued requests in parenthesis?) and the fatal
handshake failure.

Another odd log entry that I'm seeing often is this transfer() loop error:

  May  4 21:12:53 host stunnel: LOG3[14341:3085822864]: transfer() loop executes not transferring any data
  May  4 21:12:53 host stunnel: LOG3[14341:3085822864]: please report the problem to Michal.Trojnara at mirt.net
  May  4 21:12:53 host stunnel: LOG3[14341:3085822864]: socket open: rd=no wr=yes, ssl open: rd=no wr=no
  May  4 21:12:53 host stunnel: LOG3[14341:3085822864]: socket ready: rd=yes wr=no, ssl ready: rd=no wr=no
  May  4 21:12:53 host stunnel: LOG3[14341:3085822864]: ssl want: rd=no wr=no
  May  4 21:12:53 host stunnel: LOG3[14341:3085822864]: socket input buffer: 0 byte(s), ssl input buffer: 29 byte(s)
  May  4 21:12:53 host stunnel: LOG3[14341:3085822864]: check_SSL_pending=0, ssl_closing=3
  May  4 21:12:53 host stunnel: LOG5[14341:3085822864]: Connection reset: 238 bytes sent to SSL, 225 bytes sent to socket

Don't know if it's related but might as well post it along as a possible
symptom.

Thanks,
  --Robert

More information about the stunnel-users mailing list