[stunnel-users] server refuses connection by STARTTLS

Tsurutani Naoki turutani at scphys.kyoto-u.ac.jp
Sun Jan 10 23:15:36 CET 2010 

Hi,

I want to connect to SMTP server by STARTTLS, from MUA who does not support STARTTLS.
However, I cannot connect to the server with recent stunnel.

On Windows XP, my stunnel.conf is the following:
client=yes 
debug=notice
output=C:\logs\stunnel.log
service=stunnel
[smtp_server]
accept=127.0.0.1:10025
connect=smtp.example.com:587
protocol=smtp

stunnel version 4.27 or 4.29 is started as service, by
"C:\Network\stunnel\stunnel.exe" -service -install c:\home\turutani\INI\stunnel.conf

I cannot connect with OpenSSL distributed via stunnel.
Then I changed the OpenSSL DLL, and found that I can connect with OpenSSL
older than 0.9.8i, while that newer than 0.9.8j fails.
But it works by adding "sslVersion=all" or "sslVersion=SSLv2" to configuration file.

I also ran stunnel on FreeBSD, and found the same result about SSL version.

Here is a debug level log, with no "sslVersion=" or "sslVersion=SSLv3":
2010.01.08 09:50:06 LOG7[2372:3760]: RAND_status claims sufficient entropy for the PRNG
2010.01.08 09:50:06 LOG7[2372:3760]: PRNG seeded successfully
2010.01.08 09:50:06 LOG7[2372:3760]: SSL context initialized for service smtp_server
2010.01.08 09:50:06 LOG5[2372:3760]: stunnel 4.28 on x86-pc-mingw32-gnu with OpenSSL 0.9.8l 5 Nov 2009
2010.01.08 09:50:06 LOG5[2372:3760]: Threading:WIN32 SSL:ENGINE Sockets:SELECT,IPv6
2010.01.08 09:50:06 LOG5[2372:2252]: No limit detected for the number of clients
2010.01.08 09:50:06 LOG7[2372:2252]: FD 236 in non-blocking mode
2010.01.08 09:50:06 LOG7[2372:2252]: SO_REUSEADDR option set on accept socket
2010.01.08 09:50:06 LOG7[2372:2252]: smtp_server bound to 127.0.0.1:10025
2010.01.08 09:50:34 LOG7[2372:2252]: smtp_server accepted FD=244 from 127.0.0.1:1953
2010.01.08 09:50:34 LOG7[2372:2252]: Creating a new thread
2010.01.08 09:50:34 LOG7[2372:2252]: New thread created
2010.01.08 09:50:34 LOG7[2372:1036]: smtp_server started
2010.01.08 09:50:34 LOG7[2372:1036]: FD 244 in non-blocking mode
2010.01.08 09:50:34 LOG5[2372:1036]: smtp_server accepted connection from 127.0.0.1:1953
2010.01.08 09:50:34 LOG7[2372:1036]: FD 268 in non-blocking mode
2010.01.08 09:50:34 LOG6[2372:1036]: connect_blocking: connecting 133.x.y.z:587
2010.01.08 09:50:34 LOG7[2372:1036]: connect_blocking: s_poll_wait 133.x.y.z:587: waiting 10 seconds
2010.01.08 09:50:34 LOG5[2372:1036]: connect_blocking: connected 133.x.y.z:587
2010.01.08 09:50:34 LOG5[2372:1036]: smtp_server connected remote server from 192.168.3.118:1954
2010.01.08 09:50:34 LOG7[2372:1036]: Remote FD=268 initialized
2010.01.08 09:50:34 LOG5[2372:1036]: Negotiations for smtp (client side) started
2010.01.08 09:50:37 LOG7[2372:1036]:  <- 220 smtp.example.com ESMTP Postfix
2010.01.08 09:50:37 LOG7[2372:1036]:  -> 220 smtp.example.com ESMTP Postfix
2010.01.08 09:50:37 LOG7[2372:1036]:  -> EHLO localhost
2010.01.08 09:50:37 LOG7[2372:1036]:  <- 250-smtp.example.com
2010.01.08 09:50:37 LOG7[2372:1036]:  <- 250-PIPELINING
2010.01.08 09:50:37 LOG7[2372:1036]:  <- 250-SIZE 51200000
2010.01.08 09:50:37 LOG7[2372:1036]:  <- 250-VRFY
2010.01.08 09:50:37 LOG7[2372:1036]:  <- 250-ETRN
2010.01.08 09:50:37 LOG7[2372:1036]:  <- 250-STARTTLS
2010.01.08 09:50:37 LOG7[2372:1036]:  <- 250 8BITMIME
2010.01.08 09:50:37 LOG7[2372:1036]:  -> STARTTLS
2010.01.08 09:50:37 LOG7[2372:1036]:  <- 220 Ready to start TLS
2010.01.08 09:50:37 LOG5[2372:1036]: Protocol negotiations succeeded
2010.01.08 09:50:37 LOG7[2372:1036]: SSL state (connect): before/connect initialization
2010.01.08 09:50:37 LOG7[2372:1036]: SSL state (connect): SSLv3 write client hello A
2010.01.08 09:50:40 LOG3[2372:1036]: SSL_connect: Peer suddenly disconnected
2010.01.08 09:50:40 LOG5[2372:1036]: Connection reset: 0 bytes sent to SSL, 0 bytes sent to socket
2010.01.08 09:50:40 LOG7[2372:1036]: smtp_server finished (0 left)

with "sslVersion=all",
2010.01.08 09:45:33 LOG7[2664:3880]: RAND_status claims sufficient entropy for the PRNG
2010.01.08 09:45:33 LOG7[2664:3880]: PRNG seeded successfully
2010.01.08 09:45:34 LOG7[2664:3880]: SSL context initialized for service smtp_server
2010.01.08 09:45:34 LOG5[2664:3880]: stunnel 4.28 on x86-pc-mingw32-gnu with OpenSSL 0.9.8l 5 Nov 2009
2010.01.08 09:45:34 LOG5[2664:3880]: Threading:WIN32 SSL:ENGINE Sockets:SELECT,IPv6
2010.01.08 09:45:34 LOG5[2664:2408]: No limit detected for the number of clients
2010.01.08 09:45:34 LOG7[2664:2408]: FD 236 in non-blocking mode
2010.01.08 09:45:34 LOG7[2664:2408]: SO_REUSEADDR option set on accept socket
2010.01.08 09:45:34 LOG7[2664:2408]: smtp_server bound to 127.0.0.1:10025
2010.01.08 09:46:05 LOG7[2664:2408]: smtp_server accepted FD=244 from 127.0.0.1:1944
2010.01.08 09:46:05 LOG7[2664:2408]: Creating a new thread
2010.01.08 09:46:05 LOG7[2664:2408]: New thread created
2010.01.08 09:46:05 LOG7[2664:2968]: smtp_server started
2010.01.08 09:46:05 LOG7[2664:2968]: FD 244 in non-blocking mode
2010.01.08 09:46:05 LOG5[2664:2968]: smtp_server accepted connection from 127.0.0.1:1944
2010.01.08 09:46:05 LOG7[2664:2968]: FD 268 in non-blocking mode
2010.01.08 09:46:05 LOG6[2664:2968]: connect_blocking: connecting 133.x.y.z:587
2010.01.08 09:46:05 LOG7[2664:2968]: connect_blocking: s_poll_wait 133.x.y.z:587: waiting 10 seconds
2010.01.08 09:46:05 LOG5[2664:2968]: connect_blocking: connected 133.x.y.z:587
2010.01.08 09:46:05 LOG5[2664:2968]: smtp_server connected remote server from 192.168.3.118:1945
2010.01.08 09:46:05 LOG7[2664:2968]: Remote FD=268 initialized
2010.01.08 09:46:05 LOG5[2664:2968]: Negotiations for smtp (client side) started
2010.01.08 09:46:05 LOG7[2664:2968]:  <- 220 smtp.example.com ESMTP Postfix
2010.01.08 09:46:05 LOG7[2664:2968]:  -> 220 smtp.example.com ESMTP Postfix
2010.01.08 09:46:05 LOG7[2664:2968]:  -> EHLO localhost
2010.01.08 09:46:05 LOG7[2664:2968]:  <- 250-smtp.example.com
2010.01.08 09:46:05 LOG7[2664:2968]:  <- 250-PIPELINING
2010.01.08 09:46:05 LOG7[2664:2968]:  <- 250-SIZE 51200000
2010.01.08 09:46:05 LOG7[2664:2968]:  <- 250-VRFY
2010.01.08 09:46:05 LOG7[2664:2968]:  <- 250-ETRN
2010.01.08 09:46:05 LOG7[2664:2968]:  <- 250-STARTTLS
2010.01.08 09:46:05 LOG7[2664:2968]:  <- 250 8BITMIME
2010.01.08 09:46:05 LOG7[2664:2968]:  -> STARTTLS
2010.01.08 09:46:05 LOG7[2664:2968]:  <- 220 Ready to start TLS
2010.01.08 09:46:05 LOG5[2664:2968]: Protocol negotiations succeeded
2010.01.08 09:46:05 LOG7[2664:2968]: SSL state (connect): before/connect initialization
2010.01.08 09:46:05 LOG7[2664:2968]: SSL state (connect): SSLv2/v3 write client hello A
2010.01.08 09:46:05 LOG7[2664:2968]: SSL state (connect): SSLv3 read server hello A
2010.01.08 09:46:05 LOG7[2664:2968]: SSL state (connect): SSLv3 read server certificate A
2010.01.08 09:46:05 LOG7[2664:2968]: SSL state (connect): SSLv3 read server key exchange A
2010.01.08 09:46:05 LOG7[2664:2968]: SSL state (connect): SSLv3 read server done A
2010.01.08 09:46:05 LOG7[2664:2968]: SSL state (connect): SSLv3 write client key exchange A
2010.01.08 09:46:05 LOG7[2664:2968]: SSL state (connect): SSLv3 write change cipher spec A
2010.01.08 09:46:05 LOG7[2664:2968]: SSL state (connect): SSLv3 write finished A
2010.01.08 09:46:05 LOG7[2664:2968]: SSL state (connect): SSLv3 flush data
2010.01.08 09:46:05 LOG7[2664:2968]: SSL state (connect): SSLv3 read finished A
2010.01.08 09:46:05 LOG7[2664:2968]:    1 items in the session cache
2010.01.08 09:46:05 LOG7[2664:2968]:    1 client connects (SSL_connect())
2010.01.08 09:46:05 LOG7[2664:2968]:    1 client connects that finished
2010.01.08 09:46:05 LOG7[2664:2968]:    0 client renegotiations requested
2010.01.08 09:46:05 LOG7[2664:2968]:    0 server connects (SSL_accept())
2010.01.08 09:46:05 LOG7[2664:2968]:    0 server connects that finished
2010.01.08 09:46:05 LOG7[2664:2968]:    0 server renegotiations requested
2010.01.08 09:46:05 LOG7[2664:2968]:    0 session cache hits
2010.01.08 09:46:05 LOG7[2664:2968]:    0 external session cache hits
2010.01.08 09:46:05 LOG7[2664:2968]:    0 session cache misses
2010.01.08 09:46:05 LOG7[2664:2968]:    0 session cache timeouts
2010.01.08 09:46:05 LOG6[2664:2968]: SSL connected: new session negotiated
2010.01.08 09:46:05 LOG6[2664:2968]: Negotiated ciphers: DHE-RSA-AES256-SHA SSLv3 Kx=DH Au=RSA Enc=AES(256) Mac=SHA1
2010.01.08 09:46:05 LOG7[2664:2968]: SSL socket closed on SSL_read
2010.01.08 09:46:05 LOG7[2664:2968]: Socket write shutdown
2010.01.08 09:46:05 LOG5[2664:2968]: Connection closed: 625 bytes sent to SSL, 286 bytes sent to socket
2010.01.08 09:46:05 LOG7[2664:2968]: smtp_server finished (0 left)
2010.01.08 09:50:06 LOG7[2372:3760]: RAND_status claims sufficient entropy for the PRNG

with "sslVersion=SSLv2",
2010.01.08 09:50:50 LOG7[2692:3460]: RAND_status claims sufficient entropy for the PRNG
2010.01.08 09:50:50 LOG7[2692:3460]: PRNG seeded successfully
2010.01.08 09:50:50 LOG7[2692:3460]: SSL context initialized for service smtp_server
2010.01.08 09:50:50 LOG5[2692:3460]: stunnel 4.28 on x86-pc-mingw32-gnu with OpenSSL 0.9.8l 5 Nov 2009
2010.01.08 09:50:50 LOG5[2692:3460]: Threading:WIN32 SSL:ENGINE Sockets:SELECT,IPv6
2010.01.08 09:50:50 LOG5[2692:2496]: No limit detected for the number of clients
2010.01.08 09:50:50 LOG7[2692:2496]: FD 236 in non-blocking mode
2010.01.08 09:50:50 LOG7[2692:2496]: SO_REUSEADDR option set on accept socket
2010.01.08 09:50:50 LOG7[2692:2496]: smtp_server bound to 127.0.0.1:10025
2010.01.08 09:51:04 LOG7[2692:2496]: smtp_server accepted FD=244 from 127.0.0.1:1955
2010.01.08 09:51:04 LOG7[2692:2496]: Creating a new thread
2010.01.08 09:51:04 LOG7[2692:2496]: New thread created
2010.01.08 09:51:04 LOG7[2692:2056]: smtp_server started
2010.01.08 09:51:04 LOG7[2692:2056]: FD 244 in non-blocking mode
2010.01.08 09:51:04 LOG5[2692:2056]: smtp_server accepted connection from 127.0.0.1:1955
2010.01.08 09:51:04 LOG7[2692:2056]: FD 268 in non-blocking mode
2010.01.08 09:51:04 LOG6[2692:2056]: connect_blocking: connecting 133.x.y.z:587
2010.01.08 09:51:04 LOG7[2692:2056]: connect_blocking: s_poll_wait 133.x.y.z:587: waiting 10 seconds
2010.01.08 09:51:04 LOG5[2692:2056]: connect_blocking: connected 133.x.y.z:587
2010.01.08 09:51:04 LOG5[2692:2056]: smtp_server connected remote server from 192.168.3.118:1956
2010.01.08 09:51:04 LOG7[2692:2056]: Remote FD=268 initialized
2010.01.08 09:51:04 LOG5[2692:2056]: Negotiations for smtp (client side) started
2010.01.08 09:51:04 LOG7[2692:2056]:  <- 220 smtp.example.com ESMTP Postfix
2010.01.08 09:51:04 LOG7[2692:2056]:  -> 220 smtp.example.com ESMTP Postfix
2010.01.08 09:51:04 LOG7[2692:2056]:  -> EHLO localhost
2010.01.08 09:51:04 LOG7[2692:2056]:  <- 250-smtp.example.com
2010.01.08 09:51:04 LOG7[2692:2056]:  <- 250-PIPELINING
2010.01.08 09:51:04 LOG7[2692:2056]:  <- 250-SIZE 51200000
2010.01.08 09:51:04 LOG7[2692:2056]:  <- 250-VRFY
2010.01.08 09:51:04 LOG7[2692:2056]:  <- 250-ETRN
2010.01.08 09:51:04 LOG7[2692:2056]:  <- 250-STARTTLS
2010.01.08 09:51:04 LOG7[2692:2056]:  <- 250 8BITMIME
2010.01.08 09:51:04 LOG7[2692:2056]:  -> STARTTLS
2010.01.08 09:51:04 LOG7[2692:2056]:  <- 220 Ready to start TLS
2010.01.08 09:51:04 LOG5[2692:2056]: Protocol negotiations succeeded
2010.01.08 09:51:04 LOG7[2692:2056]: SSL state (connect): before/connect initialization
2010.01.08 09:51:04 LOG7[2692:2056]: SSL state (connect): SSLv2 write client hello A
2010.01.08 09:51:04 LOG7[2692:2056]: SSL state (connect): SSLv2 read server hello A
2010.01.08 09:51:04 LOG7[2692:2056]: SSL state (connect): SSLv2 write client master key A
2010.01.08 09:51:04 LOG7[2692:2056]: SSL state (connect): SSLv2 client start encryption
2010.01.08 09:51:04 LOG7[2692:2056]: SSL state (connect): SSLv2 write client finished A
2010.01.08 09:51:04 LOG7[2692:2056]: SSL state (connect): SSLv2 read server verify A
2010.01.08 09:51:04 LOG7[2692:2056]: SSL state (connect): SSLv2 read server finished A
2010.01.08 09:51:04 LOG7[2692:2056]:    1 items in the session cache
2010.01.08 09:51:04 LOG7[2692:2056]:    1 client connects (SSL_connect())
2010.01.08 09:51:04 LOG7[2692:2056]:    1 client connects that finished
2010.01.08 09:51:04 LOG7[2692:2056]:    0 client renegotiations requested
2010.01.08 09:51:04 LOG7[2692:2056]:    0 server connects (SSL_accept())
2010.01.08 09:51:04 LOG7[2692:2056]:    0 server connects that finished
2010.01.08 09:51:04 LOG7[2692:2056]:    0 server renegotiations requested
2010.01.08 09:51:04 LOG7[2692:2056]:    0 session cache hits
2010.01.08 09:51:04 LOG7[2692:2056]:    0 external session cache hits
2010.01.08 09:51:04 LOG7[2692:2056]:    0 session cache misses
2010.01.08 09:51:04 LOG7[2692:2056]:    0 session cache timeouts
2010.01.08 09:51:04 LOG6[2692:2056]: SSL connected: new session negotiated
2010.01.08 09:51:04 LOG6[2692:2056]: Negotiated ciphers: DES-CBC3-MD5 SSLv2 Kx=RSA Au=RSA Enc=3DES(168) Mac=MD5 
2010.01.08 09:51:04 LOG7[2692:2056]: SSL closed on SSL_read
2010.01.08 09:51:04 LOG7[2692:2056]: Socket write shutdown
2010.01.08 09:51:04 LOG7[2692:2056]: Socket closed on read
2010.01.08 09:51:04 LOG7[2692:2056]: SSL write shutdown
2010.01.08 09:51:04 LOG5[2692:2056]: Connection closed: 626 bytes sent to SSL, 286 bytes sent to socket
2010.01.08 09:51:04 LOG7[2692:2056]: smtp_server finished (0 left)

However, with OpenSSL older than 0.9.8i it can connect without "sslVersion=all" or
with "sslVersion=SSLv3", and log tells SSLv3 was used.

Why stunnel cannot connect with OpenSSL newer than 0.9.8j ?


--- 
Tsurutani Naoki
turutani at scphys.kyoto-u.ac.jp

More information about the stunnel-users mailing list