Análisis de pérdida de conexión | 421 4.4.2 host Error: timeout exceeded

[Read this post in English]

En este post mostramos el análisis de otro error común con el código 421 4.4.2 host Error: timeout exceeded que se refiere a problemas de red o conexión entre servidores de correo. Los síntomas que se pueden apreciar en esta condición es que el servidor Postfix (IMSVA) no es capaz de aceptar la totalidad de los correos que recibe y el servidor de correo remitente comienza a encolar.

A continuación mostramos los logs de un servidor Sendmail que no puede enviar correo hacia un servidor Postfix (IMSVA).

user@company.com... Connecting to postfix.localdomain via relay...
 220 ESMTP
 >>> EHLO sendmail.localdomain
 250-postfix.localdomain
 250-PIPELINING
 250-SIZE 31457280
 250-ETRN
 250-ENHANCEDSTATUSCODES
 250-8BITMIME
 250 DSN
 >>> MAIL From:<user@company.com> SIZE=4178
 250 2.1.0 Ok
 >>> RCPT To:<external@company2.com>
 >>> DATA
 250 2.1.5 Ok
 354 End data with <CR><LF>.<CR><LF>
 company3.com: Name server timeout
 timeout writing message to postfix.com: Broken pipe
 user@company.com... Deferred
 Closing connection to postfix.localdomain.

La mejor forma de entender este tipo de errores es haciendo una captura de paquetes mientras se replica el problema, así podemos ver en tiempo real todos los paquetes intercambiados y analizar el comportamiento de ambos servidores. Siempre que sea posible es preferible hacer la captura en ambos servidores para comparar que lo que uno envía es lo que el otro recibe, sin embargo el hecho de contar al menos con la captura de nuestro propio servidor nos ayudará a determinar si el problema es nuestro o del otro dominio/server.

El comando tcpdump para realizar esta captura es el siguiente:

tcpdump port 25 –s0 –w captura.cap

La siguiente imagen de Wireshark muestra la captura realizada en el servidor Postfix para efectuar el análisis.

 dsn421

Cuando analizamos paquetes de red con Wireshark, vemos que la primer columna (No.) indica el número del paquete así que describiremos cada paso utilizando esos números como referencia.

90: Sendmail envía simultáneamente dos comandos: RCPT y DATA.

91: Postfix acepta el comando RCPT. Esto lo sabemos porque la respuesta es 250 2.1.5 Ok

93: Postfix acepta el comando DATA. Esto lo sabemos porque la respuesta es un código 354. A partir de aquí, Postfix esperará a que Sendmail le mande el contenido del correo. Observamos que este paquete tiene lugar a las 09:56:02 (segunda columna de Wireshark “Time”).

94: Sendmail envía un paquete TCP con el flag ACK activo indicando que aceptó el último paquete TCP que Postfix mandó, lo que indica que la comunicación por red y por TCP hasta el momento está bien.

865: Aproximadamente un minuto después (09:57:01) Postfix da timeout porque no ha recibido ninguna información por parte de Sendmail, por lo que corta la comunicación con un código de estado 421 4.4.2 asumiendo que tal vez haya algún problema de red que impide que Sendmail le mande la información. Tome en cuenta que por defecto Postfix está configurado para que el demonio de recepción “smtpd” espere únicamente 60 segundos entre su respuesta y el siguiente comando ó información para dar timeout, lo que coincide perfectamente con la diferencia de tiempo entre este paquete y el anterior.

866: Debido a que Postfix cerró la conversación SMTP al no recibir respuesta, envía un paquete TCP con el flag FIN activo para indicarle a Sendmail que la sesión TCP debe terminar.

867: Curiosamente Sendmail acepta este FIN y responde con el ACK correspondiente, lo que indica que a nivel de red todo sigue bien.

1207: Medio minuto después, Sendmail comienza a enviar el contenido del correo. Tome en cuenta que para este momento Postfix ya no tiene una sesión SMTP abierta para recibir información.

1208: Como Postfix ya había cerrado esa conversación, envía un paquete TCP de RST para decirle a Sendmail que no tiene ninguna sesión TCP abierta para recibir datos. El paquete RST se utiliza para indicar que una de las partes ya no está en sincronía con la conversación TCP y se debe generar una nueva sesión en caso de que el cliente desee seguir transmitiendo datos.

 

Esta información es más que suficiente para concluir que a pesar de que no hay un problema de red entre los servidores, Sendmail está excediendo el tiempo límite que Postfix puede esperar para recibir el contenido del correo después de haber mandado su código 354. En este punto podemos afirmar con certeza que el problema no está en Postfix sino en el servidor Sendmail que está mandando el correo ya que tarda más de 60 segundos en comenzar la transferencia del cuerpo del correo.

Si regresamos a los logs de Sendmail, podremos observar que el error de “Broken pipe” se da porque está tratando de resolver la dirección IP de otro servidor de correo que ni siquiera corresponde al dominio del comando RCPT. Lo que indica una política activa que está retrasando la entrega del correo.

Company3.com: Name server timeout
 timeout writing message to postfix.com: Broken pipe
 user@company.com... Deferred
 Closing connection to postfix.localdomain.

Cuando ocurre esta situación, Postfix registrará las siguientes líneas en el archivo /var/log/maillog:

timeout after DATA (0 bytes) from unknown[xx.xx.xx.xx]

La mejor solución para este problema es obviamente identificar las políticas de filtrado / resolución que Sendmail está utilizando antes de enviar el correo ya que esto evitaría el retraso en la entrega, sin embargo, de no ser posible siempre se puede recurrir a la configuración de Postfix para mitigar el problema.

De la información que tenemos, sabemos que Sendmail tarda al menos 90 segundos en comenzar la transferencia del cuerpo del correo así que podemos aumentar el valor del timeout para el demonio smtpd de forma que le demos más tiempo antes de cerrar la sesión. Para hacer este cambio en Postfix sólo hay que ejecutar los siguientes comandos. Tome en cuenta que estos cambios son para mitigar el problema y no porque Postfix sea el que genera el error de transferencia. También tome en cuenta que los cambios propuestos no afectarán la entrega / recepción de correo ya que no habrá cortes ni reinicios de servicios en Postfix.

# postconf -e smtpd_timeout=120s
# postfix reload

Donde el valor 120s es el propuesto para nuestro ejemplo pero puede ser mayor o menor dependiendo del retraso que se observe en la captura de Wireshark.

Como siempre, esperamos que esta información sea de utilidad. Si necesitas profundizar más sobre cómo utilizar Wireshark para hacer análisis de tráfico SMTP, te recomendamos nuestro post Análisis de SMTP con Wireshark. Si quieres una descripción de los códigos de estado / error SMTP, puedes visitar nuestro post Códigos de status extendidos (SMTP). Si requieres de mayor información sobre las reglas de creación, transporte y estructura del correo electrónico te recomendamos nuestro libro Fundamentos de Correo electrónico. También te recomendamos nuestro libro Manual Avanzado de Implementación y Configuración de IMSVA donde encontrarás mayor información sobre este appliance de Trend Micro y Postfix que es el MTA que utiliza.

Finalmente te recordamos que puedes enviarnos tus preguntas y comentarios a nuestra cuenta de Twitter: @redinskala donde encontrarás más información y tips de seguridad.

Gracias por tu visita!

 

2 thoughts on “Análisis de pérdida de conexión | 421 4.4.2 host Error: timeout exceeded

  1. Pingback: Postfix Lost connection analysis: 421 4.4.2 host error: timeout exceeded | RedinSkala

  2. Pingback: Códigos de status extendidos (SMTP) | RedinSkala

Comments are closed.