[stunnel-users] Problem with Stunnel Working fine on the firstconnection and not on subsequent connections

Kevin A. McGrail kevin.mcgrail at thoughtworthy.com
Sat Nov 19 18:29:24 CET 2005 

> I'd try to disable chroot and run stunnel under strace with "foreground =
yes" option.

Mike,

When running in foreground, with or without chroot, things work as expected.
Without foreground, it did not work.

Two key differences on the logs for each:

Output of "Cleaning up the signal pipe" prior to checking the libwrap
permissions
a finish line of "ssmtp finished (0 left)" instead of "ssmtp finished (-1
left)"

(Yes, this is a dual processor box.)


It looks like the key problem lies in the regerenation of the standalone
mode.  Is there a way with v4 to just use inetd to answer on port 465,
negotiate and connect on port 25 on another host because perhaps that will
avoid the issue.

Regards,
KAM



2005.11.19 13:07:51 LOG7[3893:1024]: Key file:
/usr/local/ssl/certs/stunnel.pem
2005.11.19 13:07:51 LOG6[3893:1024]: file ulimit = 1024 (can be changed with
'ulimit -n')
2005.11.19 13:07:51 LOG6[3893:1024]: poll() used - no FD_SETSIZE limit for
file descriptors
2005.11.19 13:07:51 LOG5[3893:1024]: 500 clients allowed
2005.11.19 13:07:51 LOG7[3893:1024]: FD 4 in non-blocking mode
2005.11.19 13:07:51 LOG7[3893:1024]: FD 5 in non-blocking mode
2005.11.19 13:07:51 LOG7[3893:1024]: FD 6 in non-blocking mode
2005.11.19 13:07:51 LOG7[3893:1024]: SO_REUSEADDR option set on accept
socket
2005.11.19 13:07:51 LOG7[3893:1024]: ssmtp bound to 0.0.0.0:465
2005.11.19 13:07:51 LOG7[3893:1024]: Created pid file /stunnel.pid

[ed: 1st email]
2005.11.19 13:08:32 LOG7[3893:1024]: ssmtp accepted FD=7 from
66.149.103.32:3130
2005.11.19 13:08:32 LOG7[3898:1026]: ssmtp started
2005.11.19 13:08:32 LOG7[3898:1026]: FD 7 in non-blocking mode
2005.11.19 13:08:32 LOG7[3898:1026]: TCP_NODELAY option set on local socket
2005.11.19 13:08:32 LOG7[3898:1026]: FD 10 in non-blocking mode
2005.11.19 13:08:32 LOG7[3898:1026]: FD 11 in non-blocking mode
2005.11.19 13:08:32 LOG7[3893:1024]: Cleaning up the signal pipe
2005.11.19 13:08:32 LOG7[3898:1026]: Connection from 66.149.103.32:3130
permitted by libwrap
2005.11.19 13:08:32 LOG5[3898:1026]: ssmtp connected from 66.149.103.32:3130
2005.11.19 13:08:32 LOG7[3898:1026]: SSL state (accept): before/accept
initialization
2005.11.19 13:08:32 LOG7[3898:1026]: SSL state (accept): SSLv3 read client
hello A
2005.11.19 13:08:32 LOG7[3898:1026]: SSL state (accept): SSLv3 write server
hello A
2005.11.19 13:08:32 LOG7[3898:1026]: SSL state (accept): SSLv3 write
certificate A
2005.11.19 13:08:32 LOG7[3898:1026]: SSL state (accept): SSLv3 write server
done A
2005.11.19 13:08:32 LOG7[3898:1026]: SSL state (accept): SSLv3 flush data
2005.11.19 13:08:32 LOG7[3898:1026]: SSL state (accept): SSLv3 read client
key exchange A
2005.11.19 13:08:32 LOG7[3898:1026]: SSL state (accept): SSLv3 read finished
A
2005.11.19 13:08:32 LOG7[3898:1026]: SSL state (accept): SSLv3 write change
cipher spec A
2005.11.19 13:08:32 LOG7[3898:1026]: SSL state (accept): SSLv3 write
finished A
2005.11.19 13:08:32 LOG7[3898:1026]: SSL state (accept): SSLv3 flush data
2005.11.19 13:08:32 LOG7[3898:1026]:    1 items in the session cache
2005.11.19 13:08:32 LOG7[3898:1026]:    0 client connects (SSL_connect())
2005.11.19 13:08:32 LOG7[3898:1026]:    0 client connects that finished
2005.11.19 13:08:32 LOG7[3898:1026]:    0 client renegotiatations requested
2005.11.19 13:08:32 LOG7[3898:1026]:    1 server connects (SSL_accept())
2005.11.19 13:08:32 LOG7[3898:1026]:    1 server connects that finished
2005.11.19 13:08:32 LOG7[3898:1026]:    0 server renegotiatiations requested
2005.11.19 13:08:32 LOG7[3898:1026]:    0 session cache hits
2005.11.19 13:08:32 LOG7[3898:1026]:    1 session cache misses
2005.11.19 13:08:32 LOG7[3898:1026]:    0 session cache timeouts
2005.11.19 13:08:32 LOG6[3898:1026]: SSL accepted: new session negotiated
2005.11.19 13:08:32 LOG6[3898:1026]: Negotiated ciphers: RC4-MD5
SSLv3 Kx=RSA      Au=RSA  Enc=RC4(128)  Mac=MD5
2005.11.19 13:08:32 LOG7[3898:1026]: FD 10 in non-blocking mode
2005.11.19 13:08:32 LOG7[3898:1026]: ssmtp connecting 10.10.10.30:25
2005.11.19 13:08:32 LOG7[3898:1026]: connect_wait: waiting 10 seconds
2005.11.19 13:08:32 LOG7[3898:1026]: connect_wait: connected
2005.11.19 13:08:32 LOG7[3898:1026]: Remote FD=10 initialized
2005.11.19 13:08:32 LOG7[3898:1026]: TCP_NODELAY option set on remote socket
2005.11.19 13:08:33 LOG7[3898:1026]: Socket closed on read
2005.11.19 13:08:33 LOG7[3898:1026]: SSL write shutdown
2005.11.19 13:08:33 LOG7[3898:1026]: SSL alert (write): warning: close
notify
2005.11.19 13:08:33 LOG7[3898:1026]: SSL_shutdown retrying
2005.11.19 13:08:33 LOG7[3898:1026]: SSL doesn't need to read or write
2005.11.19 13:08:33 LOG7[3898:1026]: SSL socket closed on SSL_read
2005.11.19 13:08:33 LOG7[3898:1026]: Socket write shutdown
2005.11.19 13:08:33 LOG5[3898:1026]: Connection closed: 834 bytes sent to
SSL, 1358 bytes sent to socket
2005.11.19 13:08:33 LOG7[3898:1026]: ssmtp finished (0 left)

[ed: 2nd email]
2005.11.19 13:08:40 LOG7[3893:1024]: ssmtp accepted FD=7 from
66.149.103.32:3137
2005.11.19 13:08:40 LOG7[3900:2050]: ssmtp started
2005.11.19 13:08:40 LOG7[3900:2050]: FD 7 in non-blocking mode
2005.11.19 13:08:40 LOG7[3900:2050]: TCP_NODELAY option set on local socket
2005.11.19 13:08:40 LOG7[3900:2050]: FD 10 in non-blocking mode
2005.11.19 13:08:40 LOG7[3900:2050]: FD 11 in non-blocking mode
2005.11.19 13:08:40 LOG7[3893:1024]: Cleaning up the signal pipe
2005.11.19 13:08:40 LOG7[3900:2050]: Connection from 66.149.103.32:3137
permitted by libwrap
2005.11.19 13:08:40 LOG5[3900:2050]: ssmtp connected from 66.149.103.32:3137
2005.11.19 13:08:40 LOG7[3900:2050]: SSL state (accept): before/accept
initialization
2005.11.19 13:08:40 LOG7[3900:2050]: SSL state (accept): SSLv3 read client
hello A
2005.11.19 13:08:40 LOG7[3900:2050]: SSL state (accept): SSLv3 write server
hello A
2005.11.19 13:08:40 LOG7[3900:2050]: SSL state (accept): SSLv3 write
certificate A
2005.11.19 13:08:40 LOG7[3900:2050]: SSL state (accept): SSLv3 write server
done A
2005.11.19 13:08:40 LOG7[3900:2050]: SSL state (accept): SSLv3 flush data
2005.11.19 13:08:40 LOG7[3900:2050]: SSL state (accept): SSLv3 read client
key exchange A
2005.11.19 13:08:40 LOG7[3900:2050]: SSL state (accept): SSLv3 read finished
A
2005.11.19 13:08:40 LOG7[3900:2050]: SSL state (accept): SSLv3 write change
cipher spec A
2005.11.19 13:08:40 LOG7[3900:2050]: SSL state (accept): SSLv3 write
finished A
2005.11.19 13:08:40 LOG7[3900:2050]: SSL state (accept): SSLv3 flush data
2005.11.19 13:08:40 LOG7[3900:2050]:    2 items in the session cache
2005.11.19 13:08:40 LOG7[3900:2050]:    0 client connects (SSL_connect())
2005.11.19 13:08:40 LOG7[3900:2050]:    0 client connects that finished
2005.11.19 13:08:40 LOG7[3900:2050]:    0 client renegotiatations requested
2005.11.19 13:08:40 LOG7[3900:2050]:    2 server connects (SSL_accept())
2005.11.19 13:08:40 LOG7[3900:2050]:    2 server connects that finished
2005.11.19 13:08:40 LOG7[3900:2050]:    0 server renegotiatiations requested
2005.11.19 13:08:40 LOG7[3900:2050]:    0 session cache hits
2005.11.19 13:08:40 LOG7[3900:2050]:    2 session cache misses
2005.11.19 13:08:40 LOG7[3900:2050]:    0 session cache timeouts
2005.11.19 13:08:40 LOG6[3900:2050]: SSL accepted: new session negotiated
2005.11.19 13:08:40 LOG6[3900:2050]: Negotiated ciphers: RC4-MD5
SSLv3 Kx=RSA      Au=RSA  Enc=RC4(128)  Mac=MD5
2005.11.19 13:08:40 LOG7[3900:2050]: FD 10 in non-blocking mode
2005.11.19 13:08:40 LOG7[3900:2050]: ssmtp connecting 10.10.10.30:25
2005.11.19 13:08:40 LOG7[3900:2050]: connect_wait: waiting 10 seconds
2005.11.19 13:08:40 LOG7[3900:2050]: connect_wait: connected
2005.11.19 13:08:40 LOG7[3900:2050]: Remote FD=10 initialized
2005.11.19 13:08:40 LOG7[3900:2050]: TCP_NODELAY option set on remote socket
2005.11.19 13:08:42 LOG7[3900:2050]: Socket closed on read
2005.11.19 13:08:42 LOG7[3900:2050]: SSL write shutdown
2005.11.19 13:08:42 LOG7[3900:2050]: SSL alert (write): warning: close
notify
2005.11.19 13:08:42 LOG7[3900:2050]: SSL_shutdown retrying
2005.11.19 13:08:42 LOG7[3900:2050]: SSL doesn't need to read or write
2005.11.19 13:08:42 LOG7[3900:2050]: SSL socket closed on SSL_read
2005.11.19 13:08:42 LOG7[3900:2050]: Socket write shutdown
2005.11.19 13:08:42 LOG5[3900:2050]: Connection closed: 834 bytes sent to
SSL, 1358 bytes sent to socket
2005.11.19 13:08:42 LOG7[3900:2050]: ssmtp finished (0 left)



Without foreground, things do not continue past the first connection:
2005.11.19 13:10:32 LOG7[3910:1024]: ssmtp accepted FD=7 from
66.149.103.32:3268
2005.11.19 13:10:32 LOG7[3916:1026]: ssmtp started
2005.11.19 13:10:32 LOG7[3916:1026]: FD 7 in non-blocking mode
2005.11.19 13:10:32 LOG7[3916:1026]: TCP_NODELAY option set on local socket
2005.11.19 13:10:32 LOG7[3916:1026]: FD 10 in non-blocking mode
2005.11.19 13:10:32 LOG7[3916:1026]: FD 11 in non-blocking mode
2005.11.19 13:10:32 LOG7[3916:1026]: Connection from 66.149.103.32:3268
permitted by libwrap
2005.11.19 13:10:32 LOG5[3916:1026]: ssmtp connected from 66.149.103.32:3268
2005.11.19 13:10:32 LOG7[3916:1026]: SSL state (accept): before/accept
initialization
2005.11.19 13:10:32 LOG7[3916:1026]: SSL state (accept): SSLv3 read client
hello A
2005.11.19 13:10:32 LOG7[3916:1026]: SSL state (accept): SSLv3 write server
hello A
2005.11.19 13:10:32 LOG7[3916:1026]: SSL state (accept): SSLv3 write
certificate A
2005.11.19 13:10:32 LOG7[3916:1026]: SSL state (accept): SSLv3 write server
done A
2005.11.19 13:10:32 LOG7[3916:1026]: SSL state (accept): SSLv3 flush data
2005.11.19 13:10:32 LOG7[3916:1026]: SSL state (accept): SSLv3 read client
key exchange A
2005.11.19 13:10:32 LOG7[3916:1026]: SSL state (accept): SSLv3 read finished
A
2005.11.19 13:10:32 LOG7[3916:1026]: SSL state (accept): SSLv3 write change
cipher spec A
2005.11.19 13:10:32 LOG7[3916:1026]: SSL state (accept): SSLv3 write
finished A
2005.11.19 13:10:32 LOG7[3916:1026]: SSL state (accept): SSLv3 flush data
2005.11.19 13:10:32 LOG7[3916:1026]:    1 items in the session cache
2005.11.19 13:10:32 LOG7[3916:1026]:    0 client connects (SSL_connect())
2005.11.19 13:10:32 LOG7[3916:1026]:    0 client connects that finished
2005.11.19 13:10:32 LOG7[3916:1026]:    0 client renegotiatations requested
    2005.11.19 13:10:32 LOG7[3916:1026]:    1 server connects (SSL_accept())
2005.11.19 13:10:32 LOG7[3916:1026]:    1 server connects that finished
2005.11.19 13:10:32 LOG7[3916:1026]:    0 server renegotiatiations requested
2005.11.19 13:10:32 LOG7[3916:1026]:    0 session cache hits
2005.11.19 13:10:32 LOG7[3916:1026]:    1 session cache misses
2005.11.19 13:10:32 LOG7[3916:1026]:    0 session cache timeouts
2005.11.19 13:10:32 LOG6[3916:1026]: SSL accepted: new session negotiated
2005.11.19 13:10:32 LOG6[3916:1026]: Negotiated ciphers: RC4-MD5
SSLv3 Kx=RSA      Au=RSA  Enc=RC4(128)  Mac=MD5
2005.11.19 13:10:32 LOG7[3916:1026]: FD 10 in non-blocking mode
2005.11.19 13:10:32 LOG7[3916:1026]: ssmtp connecting 10.10.10.30:25
2005.11.19 13:10:32 LOG7[3916:1026]: connect_wait: waiting 10 seconds
2005.11.19 13:10:32 LOG7[3916:1026]: connect_wait: connected
2005.11.19 13:10:32 LOG7[3916:1026]: Remote FD=10 initialized
2005.11.19 13:10:32 LOG7[3916:1026]: TCP_NODELAY option set on remote socket
2005.11.19 13:10:33 LOG7[3916:1026]: Socket closed on read
2005.11.19 13:10:33 LOG7[3916:1026]: SSL write shutdown
2005.11.19 13:10:33 LOG7[3916:1026]: SSL alert (write): warning: close
notify
2005.11.19 13:10:33 LOG7[3916:1026]: SSL_shutdown retrying
2005.11.19 13:10:33 LOG7[3916:1026]: SSL doesn't need to read or write
2005.11.19 13:10:34 LOG7[3916:1026]: SSL socket closed on SSL_read
2005.11.19 13:10:34 LOG7[3916:1026]: Socket write shutdown
2005.11.19 13:10:34 LOG5[3916:1026]: Connection closed: 834 bytes sent to
SSL, 1353 bytes sent to socket
2005.11.19 13:10:34 LOG7[3916:1026]: ssmtp finished (-1 left)

More information about the stunnel-users mailing list