3

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

9
  • 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, 2012 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, 2012 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, 2012 at 14:27
  • No certificate warnings on the client side :(
    – Hal9000
    Mar 6, 2012 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, 2012 at 15:09

1 Answer 1

2

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

Step 1: Client sends ClientHello message proposing SSL options.
Step 2: Server responds with ServerHello message selecting the SSL options.
Step 3: Server sends its public key information in ServerKeyExchange message.
Step 4: Server concludes its part of the negotiation with ServerHelloDone message.
Step 5: Client sends session key information (encrypted with server’s public key) in ClientKeyExchange message.
Step 6: Client sends ChangeCipherSpec message to activate the negotiated options for all future messages it will send.
Step 7: Client sends Finished message to let the server check the newly activated options.
Step 8: Server sends ChangeCipherSpec message to activate the negotiated options for all future messages it will send.
Step 9: Server sends Finished message to let the client check the newly activated options.

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 here

level | information
0       Disable logging of TLS activity.
1       Log only a summary message on TLS handshake completion — no logging of client certificate trust-chain verification errors if client certificate verification is not required.
2       Also log levels during TLS negotiation.
3       Also log hexadecimal and ASCII dump of TLS negotiation process.
4       Also log hexadecimal and ASCII dump of complete transmission after STARTTLS.TTLS.

Setting this parameter to > 3 will dump everything you need.

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .