I have this really weird problem since a couple of days/weeks: more and more people are reporting problems connecting to the mail servers (Dovecot IMAP and POP3 as well as Postfix SMTP) in SSL mode.
They are running on two separate Debian 6.ß squeeze servers with identical configuration and identical SSL certificates, they being RapidSSL wildcard certificates. The configuration worked very well for over 2 years and has not been changed at all recently.
Only thing I can say is that at the end of December I renewed and therefor updated the SSL certificates. And of course I am keeping all Debian packages up-to-date.
I have been unable to find a common scenario to reproduce the problem, it happens on a variety of clients (Mozilla Thunderbird, Windows Live Mail, Apple Mail) and happens pretty randomly, and only with some users. Basically, clients report that the server unexpectedly terminates the connection. If you retry however a few seconds later, it works.
Strange thing is, this affects both Postfix AND Dovecot, however Apache seems to run fine with the same certificates.
On one of the servers there is just my mailbox, so I can exclude any server overload or limits being reached.
So I enabled debug logs on both Postfix and Dovecot.
Mar 5 20:15:24 mercury postfix/smtpd[24551]: connect from xxx.kabel-badenwuerttemberg.de[46.xxx.xxx.xxx]
Mar 5 20:15:24 mercury postfix/smtpd[24551]: setting up TLS connection from xxx.kabel-badenwuerttemberg.de[46.xxx.xxx.xxx]
Mar 5 20:15:24 mercury postfix/smtpd[24551]: xxx.kabel-badenwuerttemberg.de[46.xxx.xxx.xxx]: TLS cipher list "ALL:+RC4:@STRENGTH"
Mar 5 20:15:24 mercury postfix/smtpd[24551]: SSL_accept:before/accept initialization
Mar 5 20:15:24 mercury postfix/smtpd[24551]: SSL_accept:SSLv3 read client hello B
Mar 5 20:15:24 mercury postfix/smtpd[24551]: SSL_accept:SSLv3 write server hello A
Mar 5 20:15:24 mercury postfix/smtpd[24551]: SSL_accept:SSLv3 write certificate A
Mar 5 20:15:24 mercury postfix/smtpd[24551]: SSL_accept:SSLv3 write server done A
Mar 5 20:15:24 mercury postfix/smtpd[24551]: SSL_accept:SSLv3 flush data
Mar 5 20:15:24 mercury postfix/smtpd[24551]: **SSL_accept error** from xxx.kabel-badenwuerttemberg.de[46.xxx.xxx.xxx]: -1
Mar 5 20:15:24 mercury postfix/smtpd[24551]: lost connection after STARTTLS from xxx.kabel-badenwuerttemberg.de[46.xxx.xxx.xxx]
Mar 5 20:15:24 mercury postfix/smtpd[24551]: disconnect from xxx.kabel-badenwuerttemberg.de[46.xxx.xxx.xxx]
Mar 5 20:15:24 mercury postfix/smtpd[24551]: connect from xxx.kabel-badenwuerttemberg.de[46.xxx.xxx.xxx]
Mar 5 20:15:24 mercury postfix/smtpd[24551]: lost connection after MAIL from xxx.kabel-badenwuerttemberg.de[46.xxx.xxx.xxx]
Mar 5 20:15:24 mercury postfix/smtpd[24551]: disconnect from xxx.kabel-badenwuerttemberg.de[46.xxx.xxx.xxx]
A couple of minutes later a successful communication. Same client.
Mar 5 20:18:53 mercury postfix/smtpd[24710]: initializing the server-side TLS engine
Mar 5 20:18:53 mercury postfix/smtpd[24710]: connect from xxx.kabel-badenwuerttemberg.de[46.xxx.xxx.xxx]
Mar 5 20:18:53 mercury postfix/smtpd[24710]: setting up TLS connection from xxx.kabel-badenwuerttemberg.de[46.xxx.xxx.xxx]
Mar 5 20:18:53 mercury postfix/smtpd[24710]: xxx.kabel-badenwuerttemberg.de[46.xxx.xxx.xxx]: TLS cipher list "ALL:+RC4:@STRENGTH"
Mar 5 20:18:53 mercury postfix/smtpd[24710]: SSL_accept:before/accept initialization
Mar 5 20:18:53 mercury postfix/smtpd[24710]: SSL_accept:SSLv3 read client hello B
Mar 5 20:18:53 mercury postfix/smtpd[24710]: SSL_accept:SSLv3 write server hello A
Mar 5 20:18:53 mercury postfix/smtpd[24710]: SSL_accept:SSLv3 write certificate A
Mar 5 20:18:53 mercury postfix/smtpd[24710]: SSL_accept:SSLv3 write server done A
Mar 5 20:18:53 mercury postfix/smtpd[24710]: SSL_accept:SSLv3 flush data
Mar 5 20:18:53 mercury postfix/smtpd[24710]: SSL_accept:SSLv3 read client key exchange A
Mar 5 20:18:53 mercury postfix/smtpd[24710]: SSL_accept:SSLv3 read finished A
Mar 5 20:18:53 mercury postfix/smtpd[24710]: SSL_accept:SSLv3 write session ticket A
Mar 5 20:18:53 mercury postfix/smtpd[24710]: SSL_accept:SSLv3 write change cipher spec A
Mar 5 20:18:53 mercury postfix/smtpd[24710]: SSL_accept:SSLv3 write finished A
Mar 5 20:18:53 mercury postfix/smtpd[24710]: SSL_accept:SSLv3 flush data
Mar 5 20:18:53 mercury postfix/smtpd[24710]: Anonymous TLS connection established from xxx.kabel-badenwuerttemberg.de[46.xxx.xxx.xxx]: TLSv1 with cipher AES128-SHA (128/128 bits)
Mar 5 20:18:53 mercury postfix/smtpd[24710]: 9B3C93FA2C: client=xxx.kabel-badenwuerttemberg.de[46.xxx.xxx.xxx], sasl_method=LOGIN, sasl_username=xxx
Mar 5 20:18:53 mercury postfix/cleanup[24712]: 9B3C93FA2C: message-id=<A1DEE5BBBD1F4E4CB5BF9AD0D3B1F98F@Angus>
Mar 5 20:18:53 mercury postfix/qmgr[24412]: 9B3C93FA2C: from=<foo@bar.tld>, size=1303, nrcpt=1 (queue active)
Mar 5 20:18:53 mercury postfix/smtpd[24710]: disconnect from xxx.kabel-badenwuerttemberg.de[46.xxx.xxx.xxx]
Mar 5 20:18:53 mercury postfix/smtp[24713]: 9B3C93FA2C: to=<foo@devnull.tld>, relay=xxx.xxx.xxx[188.xxx.xxx.xxx]:25, delay=0.38, delays=0.19/0.01/0.12/0.06, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as E8FC024534)
Mar 5 20:18:53 mercury postfix/qmgr[24412]: 9B3C93FA2C: remove
Dovecot is not very communicative, this is what it says on failure:
Mar 5 22:18:23 mercury dovecot: imap-login: Disconnected (no auth attempts): rip=46.xxx.xxx.xxx, lip=188.xxx.xxx.xxx, TLS: Disconnected
Mar 5 22:18:25 mercury dovecot: imap-login: Disconnected (no auth attempts): rip=46.xxx.xxx.xxx, lip=188.xxx.xxx.xxx, TLS handshaking: Disconnected
I am desperatly trying to understand what is going on. Is it a problem derived from my new certificate? Is it a problem with the newest security-updated openssl library from debian?
I rebooted the machine, double-checked the correctness of the Certificates, disabled the Firewall, it all helped nothing…
The weirdest thing is the complete randomness of this behavior: just some users/clients exhibit the problem, plus sometimes it works for them too. Really weird…
Best Answer
All evidence so far is pointing to a client-side problem, so I'll just leave it at that.
Additional info:
According to this page, there are 9 steps to establish secure channel
According to maillog, the "ritual" aborted by client after step 4.
How to debug further
To give insight what's really happened, you should fire tcpdump in server side and compare successful case and unsuccessful one.
Another additional step is enable SSL verbosity in postfix
main.cf
. Take a look in parameter smtpd_tls_loglevel. The log level table was given hereSetting this parameter to > 3 will dump everything you need.