I'm trying to send an email through stunnel (which is running on the mail server), but I keep getting an error.
$ sudo /usr/local/sbin/stunnel 2006.12.07 15:35:27 LOG7[6092:2684407744]: Snagged 64 random bytes from /Users/jlbrown/.rnd 2006.12.07 15:35:27 LOG7[6092:2684407744]: Wrote 1024 new random bytes to /Users/jlbrown/.rnd 2006.12.07 15:35:27 LOG7[6092:2684407744]: RAND_status claims sufficient entropy for the PRNG 2006.12.07 15:35:27 LOG7[6092:2684407744]: PRNG seeded successfully 2006.12.07 15:35:27 LOG7[6092:2684407744]: Certificate: /etc/postfix/ smtpd.cert 2006.12.07 15:35:27 LOG7[6092:2684407744]: Certificate loaded 2006.12.07 15:35:27 LOG7[6092:2684407744]: Key file: /etc/postfix/ smtpd.key 2006.12.07 15:35:27 LOG7[6092:2684407744]: Private key loaded 2006.12.07 15:35:27 LOG7[6092:2684407744]: SSL context initialized for service ssmtp 2006.12.07 15:35:27 LOG5[6092:2684407744]: stunnel 4.19 on i686-apple- darwin8.8.1 with OpenSSL 0.9.7l 28 Sep 2006 2006.12.07 15:35:27 LOG5[6092:2684407744]: Threading:PTHREAD SSL:ENGINE Sockets:SELECT,IPv4 Auth:LIBWRAP 2006.12.07 15:35:27 LOG6[6092:2684407744]: file ulimit = 256 (can be changed with 'ulimit -n') 2006.12.07 15:35:27 LOG6[6092:2684407744]: FD_SETSIZE = 1024 (some systems allow to increase this value) 2006.12.07 15:35:27 LOG5[6092:2684407744]: 125 clients allowed 2006.12.07 15:35:27 LOG7[6092:2684407744]: FD 6 in non-blocking mode 2006.12.07 15:35:27 LOG7[6092:2684407744]: FD 7 in non-blocking mode 2006.12.07 15:35:27 LOG7[6092:2684407744]: FD 8 in non-blocking mode 2006.12.07 15:35:27 LOG7[6092:2684407744]: SO_REUSEADDR option set on accept socket 2006.12.07 15:35:27 LOG7[6092:2684407744]: ssmtp bound to 0.0.0.0:465 2006.12.07 15:35:27 LOG7[6093:2684407744]: Created pid file /usr/ local/var/run/stunnel/stunnel.pid 2006.12.07 15:35:52 LOG7[6093:2684407744]: ssmtp accepted FD=9 from 192.168.1.4:62929 2006.12.07 15:35:52 LOG7[6093:25188864]: ssmtp started 2006.12.07 15:35:52 LOG7[6093:25188864]: FD 9 in non-blocking mode 2006.12.07 15:35:52 LOG7[6093:25188864]: TCP_NODELAY option set on local socket 2006.12.07 15:35:52 LOG7[6093:25188864]: FD 10 in non-blocking mode 2006.12.07 15:35:52 LOG7[6093:25188864]: FD 11 in non-blocking mode 2006.12.07 15:35:52 LOG7[6093:25188864]: Connection from 192.168.1.4:62929 permitted by libwrap 2006.12.07 15:35:52 LOG7[6093:2684407744]: Cleaning up the signal pipe 2006.12.07 15:35:52 LOG5[6093:25188864]: ssmtp accepted connection from 192.168.1.4:62929 2006.12.07 15:35:52 LOG6[6093:2684407744]: Child process 6094 finished with code 0 2006.12.07 15:35:52 LOG7[6093:25188864]: SSL state (accept): before/ accept initialization 2006.12.07 15:35:52 LOG7[6093:25188864]: SSL state (accept): SSLv3 read client hello A 2006.12.07 15:35:52 LOG7[6093:25188864]: SSL state (accept): SSLv3 write server hello A 2006.12.07 15:35:52 LOG7[6093:25188864]: SSL state (accept): SSLv3 write certificate A 2006.12.07 15:35:52 LOG7[6093:25188864]: SSL state (accept): SSLv3 write server done A 2006.12.07 15:35:52 LOG7[6093:25188864]: SSL state (accept): SSLv3 flush data 2006.12.07 15:35:52 LOG3[6093:25188864]: SSL_accept: Peer suddenly disconnected 2006.12.07 15:35:52 LOG5[6093:25188864]: Connection reset: 0 bytes sent to SSL, 0 bytes sent to socket 2006.12.07 15:35:52 LOG7[6093:25188864]: ssmtp finished (0 left)
My stunnel.conf is:
cert = /etc/postfix/smtpd.cert key = /etc/postfix/smtpd.key sslVersion = all socket = l:TCP_NODELAY=1 socket = r:TCP_NODELAY=1 debug = 7 output = /var/log/stunnel.log [ssmtp] client = no accept = 465 connect = 25
Does this mean that the SMTP proxy listening on port 25 is not accepting the connection from stunnel?
Thanks,
James.
James Brown wrote:
2006.12.07 15:35:52 LOG3[6093:25188864]: SSL_accept: Peer suddenly disconnected
[cut]
Does this mean that the SMTP proxy listening on port 25 is not accepting the connection from stunnel?
No. It means that your *client* has closed the SSL socket without negotiating SSL on it. I guess you've changed the port number on a mail client without actually turning the SSL on.
Best regards, Mike
On 07/12/2006, at 7:16 PM, Michal Trojnara wrote:
James Brown wrote:
2006.12.07 15:35:52 LOG3[6093:25188864]: SSL_accept: Peer suddenly disconnected
[cut]
Does this mean that the SMTP proxy listening on port 25 is not accepting the connection from stunnel?
No. It means that your *client* has closed the SSL socket without negotiating SSL on it. I guess you've changed the port number on a mail client without actually turning the SSL on.
Ah, thanks Mike, I was thinking that it was the peer on the other side of stunnel. I changed all the stunnel settings back (I'd been fiddling trying to get it to work) and it suddenly started working again. I think I must have restarted my Mail client or something to make its SSL kick in.
Thanks for your help,
James.
On 07/12/2006, at 7:16 PM, Michal Trojnara wrote:
James Brown wrote:
2006.12.07 15:35:52 LOG3[6093:25188864]: SSL_accept: Peer suddenly disconnected
[cut]
Does this mean that the SMTP proxy listening on port 25 is not accepting the connection from stunnel?
No. It means that your *client* has closed the SSL socket without negotiating SSL on it. I guess you've changed the port number on a mail client without actually turning the SSL on.
Best regards, Mike
Thanks Mike.
Today I'm getting "SSL_read returned WANT_READ: retrying" errors.
2006.12.08 10:42:24 LOG7[6093:2684407744]: ssmtp accepted FD=9 from 192.168.1.4:49176 2006.12.08 10:42:24 LOG7[6093:25188864]: ssmtp started 2006.12.08 10:42:24 LOG7[6093:25188864]: FD 9 in non-blocking mode 2006.12.08 10:42:24 LOG7[6093:25188864]: TCP_NODELAY option set on local socket 2006.12.08 10:42:24 LOG7[6093:25188864]: FD 10 in non-blocking mode 2006.12.08 10:42:24 LOG7[6093:25188864]: FD 11 in non-blocking mode 2006.12.08 10:42:24 LOG7[6093:25188864]: Connection from 192.168.1.4:49176 permitted by libwrap 2006.12.08 10:42:24 LOG5[6093:25188864]: ssmtp accepted connection from 192.168.1.4:49176 2006.12.08 10:42:24 LOG7[6093:25188864]: SSL state (accept): before/ accept initialization 2006.12.08 10:42:24 LOG7[6093:25188864]: SSL state (accept): SSLv3 read client hello A 2006.12.08 10:42:24 LOG7[6093:25188864]: SSL state (accept): SSLv3 write server hello A 2006.12.08 10:42:24 LOG7[6093:25188864]: SSL state (accept): SSLv3 write certificate A 2006.12.08 10:42:24 LOG7[6093:25188864]: SSL state (accept): SSLv3 write server done A 2006.12.08 10:42:24 LOG7[6093:25188864]: SSL state (accept): SSLv3 flush data 2006.12.08 10:42:24 LOG7[6093:25188864]: SSL state (accept): SSLv3 read client key exchange A 2006.12.08 10:42:24 LOG7[6093:25188864]: SSL state (accept): SSLv3 read finished A 2006.12.08 10:42:24 LOG7[6093:25188864]: SSL state (accept): SSLv3 write change cipher spec A 2006.12.08 10:42:24 LOG7[6093:25188864]: SSL state (accept): SSLv3 write finished A 2006.12.08 10:42:24 LOG7[6093:25188864]: SSL state (accept): SSLv3 flush data 2006.12.08 10:42:24 LOG7[6093:25188864]: 10 items in the session cache 2006.12.08 10:42:24 LOG7[6093:25188864]: 0 client connects (SSL_connect()) 2006.12.08 10:42:24 LOG7[6093:25188864]: 0 client connects that finished 2006.12.08 10:42:24 LOG7[6093:25188864]: 0 client renegotiations requested 2006.12.08 10:42:24 LOG7[6093:25188864]: 15 server connects (SSL_accept()) 2006.12.08 10:42:24 LOG7[6093:25188864]: 12 server connects that finished 2006.12.08 10:42:24 LOG7[6093:25188864]: 0 server renegotiations requested 2006.12.08 10:42:24 LOG7[6093:25188864]: 1 session cache hits 2006.12.08 10:42:24 LOG7[6093:25188864]: 0 session cache misses 2006.12.08 10:42:24 LOG7[6093:25188864]: 1 session cache timeouts 2006.12.08 10:42:24 LOG6[6093:25188864]: SSL accepted: new session negotiated 2006.12.08 10:42:24 LOG6[6093:25188864]: Negotiated ciphers: AES128- SHA SSLv3 Kx=RSA Au=RSA Enc=AES(128) Mac=SHA1 2006.12.08 10:42:24 LOG7[6093:25188864]: FD 10 in non-blocking mode 2006.12.08 10:42:24 LOG7[6093:25188864]: ssmtp connecting 127.0.0.1:10026 2006.12.08 10:42:24 LOG7[6093:25188864]: connect_wait: waiting 10 seconds 2006.12.08 10:42:24 LOG7[6093:25188864]: connect_wait: connected 2006.12.08 10:42:24 LOG5[6093:25188864]: ssmtp connected remote server from 127.0.0.1:51638 2006.12.08 10:42:24 LOG7[6093:25188864]: Remote FD=10 initialized 2006.12.08 10:42:24 LOG7[6093:25188864]: TCP_NODELAY option set on remote socket 2006.12.08 10:42:25 LOG7[6093:25188864]: SSL_read returned WANT_READ: retrying 2006.12.08 10:42:25 LOG7[6093:25188864]: SSL_read returned WANT_READ: retrying 2006.12.08 10:43:05 LOG7[6093:25188864]: SSL_read returned WANT_READ: retrying 2006.12.08 10:43:05 LOG7[6093:25188864]: SSL_read returned WANT_READ: retrying 2006.12.08 10:43:05 LOG7[6093:25188864]: SSL_read returned WANT_READ: retrying 2006.12.08 10:43:05 LOG7[6093:25188864]: SSL_read returned WANT_READ: retrying 2006.12.08 10:43:05 LOG7[6093:25188864]: SSL_read returned WANT_READ: retrying 2006.12.08 10:43:05 LOG7[6093:25188864]: SSL_read returned WANT_READ: retrying 2006.12.08 10:43:05 LOG7[6093:25188864]: SSL_read returned WANT_READ: retrying 2006.12.08 10:43:05 LOG7[6093:25188864]: SSL_read returned WANT_READ: retrying 2006.12.08 10:43:05 LOG7[6093:25188864]: SSL_read returned WANT_READ: retrying 2006.12.08 10:43:05 LOG7[6093:25188864]: SSL_read returned WANT_READ: retrying 2006.12.08 10:43:05 LOG7[6093:25188864]: SSL_read returned WANT_READ: retrying 2006.12.08 10:43:05 LOG7[6093:25188864]: SSL_read returned WANT_READ: retrying 2006.12.08 10:43:05 LOG7[6093:25188864]: SSL_read returned WANT_READ: retrying 2006.12.08 10:43:05 LOG7[6093:25188864]: SSL_read returned WANT_READ: retrying 2006.12.08 10:43:05 LOG7[6093:25188864]: SSL_read returned WANT_READ: retrying 2006.12.08 10:44:06 LOG7[6093:25188864]: Socket closed on read 2006.12.08 10:44:06 LOG7[6093:25188864]: SSL alert (read): warning: close notify 2006.12.08 10:44:06 LOG7[6093:25188864]: SSL closed on SSL_read 2006.12.08 10:44:06 LOG7[6093:25188864]: Socket write shutdown 2006.12.08 10:44:06 LOG7[6093:25188864]: SSL write shutdown 2006.12.08 10:44:06 LOG7[6093:25188864]: SSL alert (write): warning: close notify 2006.12.08 10:44:06 LOG6[6093:25188864]: SSL_shutdown successfully sent close_notify 2006.12.08 10:44:06 LOG5[6093:25188864]: Connection closed: 481 bytes sent to SSL, 48798 bytes sent to socket 2006.12.08 10:44:06 LOG7[6093:25188864]: ssmtp finished (0 left)
I presume this means that the client (Apple's Mail.app) is mis- behaving again?
Does it mean that the message is being sent properly?
Is there anything I can do to fix this?
Thanks,
James.
James Brown wrote:
Today I'm getting "SSL_read returned WANT_READ: retrying" errors.
[cut]
Is there anything I can do to fix this?
1. Those were not errors, just debug messages. 2. Upgrade your stunnel to 4.20. Never report problems with an absolete version of stunnel.
Best regards, Mike
-
James Brown -
Michal Trojnara