Take the 2-minute tour ×
Server Fault is a question and answer site for professional system and network administrators. It's 100% free, no registration required.

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...

share|improve this question
    
How did you restart postfix & Dovecot? Could there have been some older processes that are still holding the old certificate in memory (the cert is read in at process start time)? Dovecot has a config option to specifically log SSL options verbose_ssl=yes. Give that a try and tell us what happened. –  webtoe Mar 6 '12 at 13:46
    
Thanks webtoe. I restarted Postfix & Dovecot via /etc/init.d scripts, but I also rebooted the whole machine. I already enabled verbose_ssl, it only produces those lines I pasted above, nothing more. TLS debug logging in Postfix is set to 2. –  Hal9000 Mar 6 '12 at 14:11
    
Ah well that is a lot of my suggestions down the drain. The only other thing I can think of is that user's machines have an old certificate floating around? Because the new one doesn't match the excpetion a warning is being shown and users are clicking cancel to abort? I'm clutching at straws here... –  webtoe Mar 6 '12 at 14:27
    
No certificate warnings on the client side :( –  Hal9000 Mar 6 '12 at 14:51
    
Well my only idea left is to fall back on good ol' entropy. How does /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). –  webtoe Mar 6 '12 at 15:09

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Browse other questions tagged or ask your own question.