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=<[email protected]>, 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=<[email protected]>, 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...
verbose_ssl=yes
. Give that a try and tell us what happened./proc/sys/kernel/random/entropy_avail
look? Should be around the 3000 mark (as your postfix output looks like it could be tripping up at some sort of SSL key exchange). As an aside, have you put the-v
flag on smtpd in your master.conf? That shows buckets and buckets of info. Not sure whether what you have posted from your postfix log is with this on or not (I haven't got a machine handy to check).