几天/几周以来,我遇到了这个非常奇怪的问题:越来越多的人报告在 SSL 模式下连接到邮件服务器(Dovecot IMAP 和 POP3 以及 Postfix SMTP)时出现问题。它们在两个单独的 Debian 6.ß squeeze 服务器上运行,具有相同的配置和相同的 SSL 证书,它们是 RapidSSL 通配符证书。该配置在 2 年多的时间里运行良好,最近没有任何变化。我唯一能说的是,我在 12 月底续订并更新了 SSL 证书。当然,我会让所有 Debian 软件包保持最新状态。
我无法找到重现该问题的常见场景,它发生在各种客户端(Mozilla Thunderbird、Windows Live Mail、Apple Mail)上,并且非常随机地发生,并且只发生在某些用户身上。基本上,客户端报告服务器意外终止连接。但是,如果您在几秒钟后重试,它会起作用。奇怪的是,这会影响 Postfix 和 Dovecot,但是 Apache 似乎使用相同的证书运行良好。
其中一台服务器上只有我的邮箱,因此我可以排除任何服务器过载或达到限制的情况。
因此我在 Postfix 和 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]
几分钟后,通信成功。同一个客户。
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 的沟通功能不太好,当它失败时会显示以下内容:
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
我拼命想弄明白到底发生了什么。这是我的新证书的问题吗?还是 Debian 最新安全更新的 openssl 库的问题?我重启了机器,仔细检查了证书的正确性,禁用了防火墙,但都无济于事……最奇怪的是这种行为完全是随机的:只有一些用户/客户端会出现这个问题,而且有时他们也会遇到。真的很奇怪……
答案1
到目前为止所有的证据都指向客户端问题,因此我就不多说了。
附加信息:
根据这一页,建立安全通道有9个步骤
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.
根据邮件日志,客户端在第 4 步之后中止了“仪式”。
如何进一步调试
为了了解真正发生的情况,您应该在服务器端启动 tcpdump 并比较成功的情况和不成功的情况。
另一个额外的步骤是在 Postfix 中启用 SSL 详细程度 main.cf
. 查看参数smtpd_tls_loglevel。日志级别表在此处给出
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.
将此参数设置为> 3将转储您需要的一切。