[stunnel-users] Problem with Stunnel and OpenBSD

Fri May 23 11:18:11 CEST 2008

Hello list!

I'm long time running stunnel in OpenBSD to convert popa3d into a POP3s
service, and sometimes I have problems since I upgraded to 4.x.

Yesterday morning, after months without trouble, this started to happen:

 1- When I try to get the mail, the client connects (Evolution 2.22.1.1
from Linux; but it happens with other clients too).

 2- Then it stalls at:

2008.05.23 10:47:29 LOG7[16334:0]: SSL state (accept): before/accept
initialization

 3- After 3 minutes aprox, it continues and then it connects to popa3d
and the mail is retrieved as expected.

I'm running stunnel 4.24.

I've noticed that just after rebooting the system, it works perfectly,
but after some time running... the problem appears. Restarting stunnel
doesn't fix it.

I guess the question it's: why it is stalling at SL state (accept)?
and... why it works fine just after a reboot?

Here follows some info about my setup...

stunnel.conf:

cert = /etc/ssl/private/stunnel.pem
chroot = /var/stunnel/
setuid = _stunnel
setgid = _stunnel
pid = /var/run/stunnel.pid
socket = l:TCP_NODELAY=1

[pop3s]
accept  = 995
connect = 110

stunnel -version:

stunnel 4.24 on i386-unknown-openbsd3.8 with OpenSSL 0.9.7g 11 Apr 2005
Threading:FORK SSL:ENGINE Sockets:POLL,IPv6

Global options
debug           = 5
pid             = /var/run/stunnel/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
sslVersion      = SSLv3 for client, all for server
TIMEOUTbusy     = 300 seconds
TIMEOUTclose    = 60 seconds
TIMEOUTconnect  = 10 seconds
TIMEOUTidle     = 43200 seconds
verify          = none

Output of log running with debug=7, the interesting part it's
at 2008.05.23 10:47:29:

2008.05.23 10:47:14 LOG7[28370:0]: Snagged 64 random bytes
from /dev/arandom
2008.05.23 10:47:14 LOG7[28370:0]: RAND_status claims sufficient entropy
for the PRNG
2008.05.23 10:47:14 LOG7[28370:0]: PRNG seeded successfully
2008.05.23 10:47:14 LOG7[28370:0]:
Certificate: /etc/ssl/private/stunnel.pem
2008.05.23 10:47:14 LOG7[28370:0]: Certificate loaded
2008.05.23 10:47:14 LOG7[28370:0]: Key
file: /etc/ssl/private/stunnel.pem
2008.05.23 10:47:14 LOG7[28370:0]: Private key loaded
2008.05.23 10:47:14 LOG7[28370:0]: SSL context initialized for service
pop3s
2008.05.23 10:47:14 LOG5[28370:0]: stunnel 4.24 on
i386-unknown-openbsd3.8 with OpenSSL 0.9.7g 11 Apr 2005
2008.05.23 10:47:14 LOG5[28370:0]: Threading:FORK SSL:ENGINE
Sockets:POLL,IPv6
2008.05.23 10:47:14 LOG6[28370:0]: file ulimit = 128 (can be changed
with 'ulimit -n')
2008.05.23 10:47:14 LOG6[28370:0]: poll() used - no FD_SETSIZE limit for
file descriptors
2008.05.23 10:47:14 LOG5[28370:0]: 61 clients allowed
2008.05.23 10:47:14 LOG7[28370:0]: FD 6 in non-blocking mode
2008.05.23 10:47:14 LOG7[28370:0]: FD 7 in non-blocking mode
2008.05.23 10:47:14 LOG7[28370:0]: FD 8 in non-blocking mode
2008.05.23 10:47:14 LOG7[28370:0]: SO_REUSEADDR option set on accept
socket
2008.05.23 10:47:14 LOG7[28370:0]: pop3s bound to 0.0.0.0:995
2008.05.23 10:47:14 LOG7[17739:0]: Created pid file /var/run/stunnel.pid
2008.05.23 10:47:29 LOG7[17739:0]: pop3s accepted FD=9 from
147.156.98.148:53957
2008.05.23 10:47:29 LOG7[16334:0]: pop3s started
2008.05.23 10:47:29 LOG7[16334:0]: FD 9 in non-blocking mode
2008.05.23 10:47:29 LOG7[16334:0]: TCP_NODELAY option set on local
socket
2008.05.23 10:47:29 LOG5[16334:0]: pop3s accepted connection from
147.156.98.148:53957
2008.05.23 10:47:29 LOG7[16334:0]: SSL state (accept): before/accept
initialization
2008.05.23 10:51:18 LOG7[16334:0]: SSL state (accept): SSLv3 read client
hello A
2008.05.23 10:51:18 LOG7[16334:0]: SSL state (accept): SSLv3 write
server hello A
2008.05.23 10:51:18 LOG7[16334:0]: SSL state (accept): SSLv3 write
certificate A
2008.05.23 10:51:18 LOG7[16334:0]: SSL state (accept): SSLv3 write
server done A
2008.05.23 10:51:18 LOG7[16334:0]: SSL state (accept): SSLv3 flush data
2008.05.23 10:51:18 LOG7[16334:0]: SSL state (accept): SSLv3 read client
key exchange A
2008.05.23 10:51:18 LOG7[16334:0]: SSL state (accept): SSLv3 read
finished A
2008.05.23 10:51:18 LOG7[16334:0]: SSL state (accept): SSLv3 write
change cipher spec A
2008.05.23 10:51:18 LOG7[16334:0]: SSL state (accept): SSLv3 write
finished A
2008.05.23 10:51:18 LOG7[16334:0]: SSL state (accept): SSLv3 flush data
2008.05.23 10:51:18 LOG7[16334:0]:    1 items in the session cache
2008.05.23 10:51:18 LOG7[16334:0]:    0 client connects (SSL_connect())
2008.05.23 10:51:18 LOG7[16334:0]:    0 client connects that finished
2008.05.23 10:51:18 LOG7[16334:0]:    0 client renegotiations requested
2008.05.23 10:51:18 LOG7[16334:0]:    1 server connects (SSL_accept())
2008.05.23 10:51:18 LOG7[16334:0]:    1 server connects that finished
2008.05.23 10:51:18 LOG7[16334:0]:    0 server renegotiations requested
2008.05.23 10:51:18 LOG7[16334:0]:    0 session cache hits
2008.05.23 10:51:18 LOG7[16334:0]:    1 session cache misses
2008.05.23 10:51:18 LOG7[16334:0]:    0 session cache timeouts
2008.05.23 10:51:18 LOG6[16334:0]: SSL accepted: new session negotiated
2008.05.23 10:51:18 LOG6[16334:0]: Negotiated ciphers: AES256-SHA SSLv3
Kx=RSA Au=RSA Enc=AES(256) Mac=SHA1
2008.05.23 10:51:18 LOG7[16334:0]: FD 8 in non-blocking mode
2008.05.23 10:51:18 LOG7[16334:0]: pop3s connecting 127.0.0.1:110
2008.05.23 10:51:18 LOG5[16334:0]: pop3s connected remote server from
127.0.0.1:31725
2008.05.23 10:51:18 LOG7[16334:0]: Remote FD=8 initialized
2008.05.23 10:51:20 LOG7[16334:0]: Socket closed on read
2008.05.23 10:51:20 LOG7[16334:0]: SSL write shutdown
2008.05.23 10:51:20 LOG7[16334:0]: SSL alert (write): warning: close
notify
2008.05.23 10:51:20 LOG6[16334:0]: SSL socket closed on SSL_shutdown
2008.05.23 10:51:20 LOG7[16334:0]: Socket write shutdown
2008.05.23 10:51:20 LOG5[16334:0]: Connection closed: 22453 bytes sent
to SSL, 120 bytes sent to socket
2008.05.23 10:51:20 LOG7[17739:0]: Cleaning up the signal pipe
2008.05.23 10:51:20 LOG7[17739:0]: Process 16334 finished with code 0 (0
left)
2008.05.23 10:51:45 LOG5[17739:0]: Received signal 15; terminating
2008.05.23 10:51:45 LOG7[17739:0]: removing pid
file /var/run/stunnel.pid
2008.05.23 10:51:45 LOG3[17739:0]: /var/run/stunnel.pid: No such file or
directory (2)

-- 
desarrollo y sistemas: http://www.usebox.net/
      página personal: http://www.usebox.net/jjm/