Aleatoriamente recebendo o erro Postfix SSL_accept / handshake Dovecot TLS Desconectado

Question

Eu tenho esse problema muito estranho desde alguns dias / semanas: mais e mais pessoas estão relatando problemas de conexão com os servidores de email (Dovecot IMAP e POP3, bem como SMTP Postfix) no modo SSL. Eles estão rodando em dois servidores Debian separados do Debian 6.6 com configuração idêntica e certificados SSL idênticos, sendo eles certificados curinga RapidSSL. A configuração funcionou muito bem por mais de 2 anos e não foi alterada recentemente. A única coisa que posso dizer é que no final de dezembro eu renovei e atualizei os certificados SSL. E é claro que estou mantendo todos os pacotes Debian atualizados.

Não consegui encontrar um cenário comum para reproduzir o problema, isso acontece em vários clientes (Mozilla Thunderbird, Windows Live Mail, Apple Mail) e acontece de forma bastante aleatória e apenas com alguns usuários. Basicamente, os clientes relatam que o servidor encerra a conexão inesperadamente. Se você tentar novamente alguns segundos depois, isso funcionará. O mais estranho é que isso afeta tanto o Postfix quanto o Dovecot, no entanto o Apache parece rodar bem com os mesmos certificados.

Em um dos servidores, há apenas minha caixa de correio, para que eu possa excluir qualquer sobrecarga ou limite de servidor.

Então eu ativei os logs de depuração no Postfix e no 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]

Alguns minutos depois, uma comunicação bem-sucedida. Mesmo cliente.

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

O pombo não é muito comunicativo, é o que diz no fracasso:

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

Estou desesperadamente tentando entender o que está acontecendo. É um problema derivado do meu novo certificado? É um problema com a mais nova biblioteca openssl atualizada para segurança do debian? Eu reiniciei a máquina, verifiquei a exatidão dos Certificados, desabilitei o Firewall, tudo não ajudou nada ... O mais estranho é a aleatoriedade completa desse comportamento: apenas alguns usuários / clientes exibem o problema, e às vezes também funciona para eles. Realmente estranho ...

    

Answer 1

Todas as evidências até agora apontam para um problema do lado do cliente, então vou deixar por aí mesmo.

Informação adicional:

De acordo com a esta página , existem 9 etapas para estabelecer um canal seguro

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.

De acordo com o maillog, o "ritual" é abortado pelo cliente após o passo 4.

Como depurar mais

Para dar uma ideia do que realmente aconteceu, você deve disparar o tcpdump no lado do servidor e comparar casos bem-sucedidos e malsucedidos.

Outra etapa adicional é ativar a verbosidade do SSL no postfix main.cf . Dê uma olhada no parâmetro smtpd_tls_loglevel . A tabela de nível de log foi fornecida aqui

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.

Definindo este parâmetro como > 3 despejará tudo o que você precisa.