O postfix "atingiu o tempo limite ao enviar o corpo da mensagem" para "Serviço de ESMTP do Microsoft MAIL"

Question

Por algum motivo, não podemos enviar emails maiores para um de nossos clientes. E-mails pequenos são bons, mas até mesmo uma mensagem com um anexo de 1 MB falha em entregar por várias horas - os logs do Postfix continuam preenchendo com status=deferred (conversation with customer***[IP***] timed out while sending message body) , mas eventualmente as mensagens são enviadas.

O cliente está usando o "Serviço Microsoft ESMTP MAIL, Versão: 6.0.3790.3959" (verificado com o telnet para a porta 25), embora eu não tenha certeza se essa é realmente a falha do software do destinatário. Podemos enviar e-mails sem problemas para praticamente qualquer outro lugar. O cliente confirmou que não tem esse problema com outras pessoas que enviam emails para eles. Apenas correio do nosso servidor parece ficar preso.

Eu tentei reduzir o valor de MTU da nossa interface de saída para 1000 e até 500. Outros lugares como isto ou isso mostra que há um problema raro, mas não tem soluções ou confirmações.

Abaixo está o log do Postfix de um processo típico de envio de mensagens para esse cliente. (Endereços de email substituídos por *** , servidor de email do cliente com customer*** e ip*** )

Aug 18 15:41:28 gozilla postfix/cleanup[14751]: F0DB414080: message-id=<***>

Aug 18 15:41:28 gozilla postfix/qmgr[21922]: F0DB414080: from=<***>, size=1671905, nrcpt=1 (queue active)
Aug 18 15:44:44 gozilla postfix/qmgr[14985]: F0DB414080: skipped, still being delivered
Aug 18 15:44:45 gozilla postfix/qmgr[15132]: F0DB414080: skipped, still being delivered
Aug 18 15:44:45 gozilla postfix/qmgr[15242]: F0DB414080: skipped, still being delivered
Aug 18 15:44:47 gozilla postfix/smtp[14752]: F0DB414080: to=<***>, relay=customer***[IP***], delay=199, delays=0.64/0/0.68/198, dsn=4.4.2, status=deferred (conversation with customer***[IP***] timed out while sending message body)

Aug 18 15:46:44 gozilla postfix/qmgr[15242]: F0DB414080: from=<***>, size=1671905, nrcpt=1 (queue active)
Aug 18 15:50:01 gozilla postfix/smtp[15555]: F0DB414080: to=<***>, relay=customer***[IP***]:25, delay=514, delays=317/0.01/0.17/196, dsn=4.4.2, status=deferred (conversation with customer***[IP***] timed out while sending message body)

Aug 18 15:52:52 gozilla postfix/qmgr[15242]: F0DB414080: from=<***>, size=1671905, nrcpt=1 (queue active)
Aug 18 15:56:35 gozilla postfix/smtp[15872]: F0DB414080: to=<***>, relay=customer***[IP***]:25, delay=908, delays=685/0.01/0.16/222, dsn=4.4.2, status=deferred (conversation with customer***[IP***] timed out while sending message body)

Aug 18 16:14:45 gozilla postfix/qmgr[15242]: F0DB414080: from=<***>, size=1671905, nrcpt=1 (queue active)
Aug 18 16:18:18 gozilla postfix/smtp[17065]: F0DB414080: to=<***>, relay=customer***[IP***]:25, delay=2210, delays=1997/0/0.17/213, dsn=4.4.2, status=deferred (conversation with customer***[IP***] timed out while sending message body)

Aug 18 16:23:22 gozilla postfix/qmgr[17635]: F0DB414080: from=<***>, size=1671905, nrcpt=1 (queue active)
Aug 18 16:27:23 gozilla postfix/smtp[17646]: F0DB414080: to=<***>, relay=customer***[IP***]:25, delay=2755, delays=2515/0.01/0.21/240, dsn=4.4.2, status=deferred (conversation with customer***[IP***] timed out while sending message body)

 --- cut out more lines like this ---

Aug 18 19:56:17 gozilla postfix/qmgr[18145]: F0DB414080: from=<***>, size=1671905, nrcpt=1 (queue active)
Aug 18 19:59:31 gozilla postfix/smtp[26730]: F0DB414080: to=<***>, relay=customer***[IP***]:25, delay=15484, delays=15289/0.01/0.2/194, dsn=4.4.2, status=deferred (conversation with customer***[IP***] timed out while sending message body)

Aug 18 22:21:17 gozilla postfix/qmgr[18145]: F0DB414080: from=<***>, size=1671905, nrcpt=1 (queue active)
Aug 18 22:26:01 gozilla postfix/smtp[32493]: F0DB414080: to=<***>, relay=customer***[IP***]:25, delay=24274, delays=23989/0.01/0.37/284, dsn=2.6.0, status=sent (250 2.6.0  <***> Queued mail for delivery)
Aug 18 22:26:01 gozilla postfix/qmgr[18145]: F0DB414080: removed

    

Answer 1

Oh cara, eu amo esses servidores. Quase universalmente, eles fazem uma varredura baseada em conteúdo dos corpos das mensagens e, em seguida, enviam respostas não-200 para o comando DATA, caso não gostem do conteúdo. Isso é bom, em princípio, mas quando você obtém uma porcaria de lixo com poucos recursos em execução no Exchange e algum desperdício de espaço em disco com excesso de peso fazendo a varredura, a máquina funciona como melaço e todos os outros passam o tempo.

Sim, em teoria, isso pode ser um problema de MTU, como você sugeriu, mas na prática isso é bastante improvável - se você conseguir passar uma mensagem de 2000 bytes, isso refuta essa teoria (e não há muitas mensagens menos de 2000 bytes, incluindo cabeçalhos, lá fora). Um tcpdump no seu final pode confirmar isso - se for um problema no nível do TCP, você verá tentativas de retransmitir o pacote em tamanho normal; se for um problema remoto de MTA-slow, não haverá retransmissões, e o ponto de parada será quando o final enviar o fechamento " . ".

Dado que a extremidade distante parece sem noção ("todo mundo mais não tem um problema", eu apenas aumentaria o tempo limite do Postfix para alguma figura significativamente maior e deixaria as coisas como estão). As três configurações que você deseja analisar são smtp_data_done_timeout , smtp_data_xfer_timeout e smtp_data_init_timeout (aproximadamente nessa ordem de importância). Como você pode ver, os padrões são muito generosos, então a necessidade de aumentá-los realmente indica o quanto a parte mais distante é mais corpulenta.