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(a)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
