Análisis de pérdida de conexión en IMSVA (dsn=4.4.2)

En este post presentamos la metodología que utilizamos en un caso real donde los servidores IMSVA presentaban un problema de encolamiento y retraso en la entrega de correo. Esperamos que pueda ser de utilidad para diagnosticar este y otro tipo de problemas similares.

 

Problema: En el Message Tracking de IMSVA se observa que varios correos se están quedando encolados en Deferred y el usuario final percibe un retraso de 15, 30 ó más minutos en la recepción de su correo. El Message Tracking muestra estos correos como:

Passed IMSVA scan, deferred

En la sección de cuarentenas, pestaña de deferred vemos estos correos con el siguiente error:

dsn=4.4.2, status=deferred (lost connection with xx.xx.xx.xx[xx.xx.xx.xx] while sending end of data — message may be sent more than once)

donde xx.xx.xx.xx es la IP de un balanceador al que se entrega el correo. Dicho balanceador se encarga de entregar el correo a 3 servidores de correo Postfix que son los MTA Internos de la empresa.

Este tipo de eventos ocurren de forma aleatoria a cualquier hora del día, pero pasan frecuentemente y diario. En este caso real, estamos hablando de dos equipos IMSVA que reciben el correo de internet que entregan el correo a tres servidores Postfix internos a través de otro balanceador y pasando por un switch CISCO.

 

Diagnóstico.

En base a la información preliminar con que contamos podemos sacar algunas conclusiones que nos ayudarán a encontrar la causa raíz de este problema:

  1. El correo no se está perdiendo ya que se está encolando dentro del IMSVA al no poder entregar el correo al balanceador. Sin embargo, cabe aclarar que el correo sólo durará encolado en IMSVA por 24 horas que es el tiempo por defecto indicado en el parámetro:

 

maximal_queue_lifetime = 1d (/opt/trend/imss/postfix/etc/postfix/main.cf)

 

  1. IMSVA está funcionando correctamente pues vemos que el maillog está registrando eventos lo que indica que el Postfix de IMSVA está trabajando correctamente. Además el Message Tracking indica que los correos han pasado satisfactoriamente el escaneo por lo que podemos descartar un problema del scanner.
  2. Del punto anterior también podemos concluir que el problema debe encontrarse en la red o en el servidor de correo interno al que se le está entregando el correo.
  3. El punto anterior se confirma por el código de error recibido (DSN=4.4.2) que de acuerdo al RFC 3463 de códigos extendidos para SMTP indica que se trata de un error que un MTA puede asumir cuando el equipo que está enviando el correo deja de recibir respuestas del SMTP Server. En estas circunstancias, el SMTP client no puede confirmar si los datos que envió llegaron satisfactoriamente al SMTP Server y tampoco puede saber en qué estado se encuentra el SMTP Server. Para justificar el encolamiento de este correo, el RFC le permite al SMTP Client asumir este error para que el correo permanezca encolado mientras se corrige el problema de red y ambos servidores puedan conectarse otra vez.
  4. Por último podemos concluir también que tanto IMSV A como el servidor de correo interno estaban transfiriendo un correo cuando ocurrió la falla. Esto implica que ya había una sesión SMTP establecida y es por esto que IMSVA puede loguear estas líneas en el archivo maillog. Si esto no fuera cierto, y no hubiera habido una sesión SMTP establecida veríamos un error del tipo “connection timeout” lo que indicaría que el problema es que el balanceador o el MTA interno están abajo o el puerto 25 está cerrado.

Esta información es suficiente para saber qué datos necesitamos recolectar para encontrar la causa raíz del problema.

  1. Necesitamos una captura de paquetes de red ejecutados de forma simultánea en los dos servidores IMSVA de perímetro y en los tres MTA Postfix que son los servidores que reciben el correo del IMSVA a través del balanceador. Esta información nos ayudará a comparar los paquetes antes y después de su paso por el balanceador, y así podremos ver cualquier alteración que se esté dando en un equipo intermedio.
  2. Necesitamos recolectar todos los archivos maillog de los dos IMSVA y de los 3 MTA Postfix después de haber replicado el problema.

Necesitamos recolectar información en estos 5 equipos de forma simultánea porque tanto los dos IMSVA como los tres Postfix internos están siendo balanceados, por lo que nunca sabemos por qué equipo pasa un correo en un momento dado. Las capturas de paquetes dentro de los dos IMSVA se realiza con el siguiente comando cada 10 minutos con el fin de que los archivos no resulten muy grandes:

# tcpdump port 25 –s0 –w captura.cap

Si el evento no se ha replicado en 10 minutos cortamos este comando en los 5 equipos y volvemos a iniciar las capturas otra vez. Repetimos el proceso hasta que el evento se haya producido.

Para saber que el evento se replicó estaremos buscando la cadena del dsn=4.4.2 en los dos equipos IMSVA. Cuando veamos pasar esta línea, dejaremos corriendo las capturas por 10 minutos más para asegurarnos de capturar la mayor cantidad de evidencia.

# tail  -f /var/log/maillog |grep “lost connection with xx.xx.xx.xx[xx.xx.xx.xx] while sending”

Cuando hayamos logrado replicar el problema detenemos las capturas y hacemos una copia de todos los archivos maillog para que estos no vayan a rotar y perdamos información. Sacamos los archivos de captura y los maillog para analizarlos en una máquina windows que tenga wireshark instalado.

NOTA: En nuestro caso la captura comenzó a las 11:33 horas, esta hora se tomará como referencia para el análisis de paquetes de red

 

Análisis del archivo maillog

El primer paso en este tipo de análisis es identificar el comportamiento que está teniendo IMSVA para confirmar la razón exacta por la que está encolando correo en Deferred. El primero archivo que vamos a analizar será el maillog del IMSVA en el que vimos que se replicó el problema. El otro maillog del otro IMSVA lo podemos desechar.

Para analizar el maillog lo podemos hacer con cualquier editor de texto como notepad. Sin embargo, hay una herramienta que recomendamos para este tipo de análisis llamada Notepad++ que se puede descargar de forma gratuita desde internet.

Abrimos el maillog en Notepad++ ó en el editor de texto de su preferencia y comenzamos por buscar todas las líneas que contengan la cadena “dsn=4.4.2”y hacemos una búsqueda completa en todo el documento (Find All in Current Document)  como se muestra a continuación:

 dsn442_10

Imagen 1. Buscando todas las líneas que contengan DSN=4.4.2

Ahora copiamos todas las líneas que resultaron en la búsqueda y las pegamos en un nuevo documento de Notepad++:

 dsn442_11

Imagen 2. Seleccionar todas las líneas que contienen el error

Ahora hacemos una nueva búsqueda en el nuevo documento para seleccionar sólo las líneas donde aparezca que la conexión se está perdiendo específicamente hacia el servidor interno, esto para descartar cualquier error que corresponda a entregas fallidas hacia Internet por otros motivos. Así podremos centrar nuestra investigación sobre evidencia más específica.

Ahora contamos con un archivo que contiene únicamente errores del tipo dsn=4.4.2 por desconexiones de red hacia la IP de nuestro balanceador.

El siguiente paso en el análisis es ubicar la ventana de tiempo aproximada en la que ocurrió el error, esto para poder identificar de forma exacta tanto las líneas del maillog como los paquetes de red que estaban en tránsito en ese momento. En nuestro ejemplo la ventana de tiempo es aproximadamente a las 11:33 am por lo que ubicaremos esas líneas en el archivo con el que estamos trabajando.

dsn442_12

Imagen 3. Errores de conexión de IMSVA

Estas líneas ya nos dan una idea más clara de lo que está ocurriendo con el IMSVA cuando ocurre el error de red. La siguiente tabla muestra un resumen de los hallazgos del maillog:

Feb 28 11:32:31 imsva postfix/smtp[18400]: 4DD834502B7: to=<user@domain.com>, relay=xx.xx.xx.xx[xx.xx.xx.xx]:25, delay=173274, delays=173257/7.4/0.01/10, dsn=4.4.2, status=deferred (lost connection with xx.xx.xx.xx[xx.xx.xx.xx] while sending end of data — message may be sent more than once)Feb 28 11:32:31 imsva postfix/smtp[18400]: 4DD834502B7: to=<user@domain.com>, relay=xx.xx.xx.xx[xx.xx.xx.xx]:25, delay=173274, delays=173257/7.4/0.01/10, dsn=4.4.2, status=deferred (lost connection with xx.xx.xx.xx[xx.xx.xx.xx] while sending end of data — message may be sent more than once)
Feb 28 11:34:39 imsva postfix/smtp[18257]: B93A62600D1: to=<user@domain.com>, relay=xx.xx.xx.xx[xx.xx.xx.xx]:25, delay=170229, delays=170084/145/0/0.01, dsn=4.4.2, status=deferred (lost connection with xx.xx.xx.xx[xx.xx.xx.xx] while sending message body)Feb 28 11:34:39 imsva postfix/smtp[18257]: B93A62600D1: to=<user@domain.com>, relay=xx.xx.xx.xx[xx.xx.xx.xx|]:25, delay=170229, delays=170084/145/0/0.01, dsn=4.4.2, status=deferred (lost connection with xx.xx.xx.xx[xx.xx.xx.xx] while sending message body)Feb 28 11:34:39 imsva postfix/smtp[18257]: B93A62600D1: to=<user@domain.com>, relay=xx.xx.xx.xx[xx.xx.xx.xx]:25, delay=170229, delays=170084/145/0/0.01, dsn=4.4.2, status=deferred (lost connection with xx.xx.xx.xx[xx.xx.xx.xx] while sending message body)
Feb 28 11:37:27 imsva postfix/smtp[18259]: 08B8A23727E: to=<user@domain.com>, relay=xx.xx.xx.xx[xx.xx.xx.xx]:25, delay=239046, delays=238733/0.6/0/313, dsn=4.4.2, status=deferred (lost connection with xx.xx.xx.xx[xx.xx.xx.xx] while sending end of data — message may be sent more than once)
Feb 28 11:37:30 imsva postfix/smtp[18383]: DE006231956: to=<user@domain.com>, relay=xx.xx.xx.xx[xx.xx.xx.xx]:25, delay=165866, delays=165550/7.1/0/309, dsn=4.4.2, status=deferred (lost connection with xx.xx.xx.xx[xx.xx.xx.xx] while sending end of data — message may be sent more than once)
Feb 28 11:39:50 imsva postfix/smtp[18266]: C6C05235C9A: to=<user@domain.com>, relay=xx.xx.xx.xx[xx.xx.xx.xx]:25, delay=587488, delays=587032/145/0.01/311, dsn=4.4.2, status=deferred (lost connection with xx.xx.xx.xx[xx.xx.xx.xx] while sending end of data — message may be sent more than once)
Feb 28 11:39:50 imsva postfix/qmgr[17889]: B727529008C: to=<user@domain.com>, relay=none, delay=171975, delays=171519/456/0/0, dsn=4.4.2, status=deferred (delivery temporarily suspended: lost connection with xx.xx.xx.xx[xx.xx.xx.xx] while sending end of data — message may be sent more than once)
Feb 28 11:54:51 imsva postfix/smtp[18382]: EC3FE3502E1: to=<user@domain.com>, relay=xx.xx.xx.xx[xx.xx.xx.xx]:25, delay=0.08, delays=0.04/0/0.02/0.03, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as A458A170CAA)

Tabla 1. Resumen de correos con problemas de desconexión

A partir de la información de esta tabla encontramos los siguientes puntos:

  1. El log muestra la entrega fallida de 5 correos consecutivos. Entre ellos no hubo ninguna entrega satisfactoria hacia la IP del balanceador. Tome en cuenta que en el log pueden aparecer más de una línea por cada correo, pero la forma de identificar que se trata de un correo único sin importar el número de líneas es que todas tienen el mismo identificador interno.
  2. Los identificadores de estos 5 correos son: 4DD834502B7, B93A62600D1, 08B8A23727E, DE006231956, C6C05235C9A.
  3. Los retrasos experimentados en la entrega de este correo hacia el balanceador de acuerdo a la última cifra del parámetro delays mostrado en las mismas líneas del log son los siguientes:

 

  • delays=173257/7.4/0.01/10. Este correo tuvo un retraso de 10 segundos
  • delays=170084/145/0/0.01. Este correo tuvo un retraso de 0.01 segundos
  • delays=238733/0.6/0/313. Este correo tuvo un retraso de 313 segundos
  • delays=165550/7.1/0/309. Este correo tuvo un retraso de 309 segundos
  • delays=587032/145/0.01/311. Este correo tuvo un retraso de 311 segundos

Tome en cuenta que los valores de cada columna corresponden en orden a los demonios smtpd, cleanup, qmgr y smtp. Se observa que la primer columna tiene valores muy elevados por ejemplo, el primer correo muestra que lleva 173257 segundos (2 días) encolado sin poder salir del IMSVA.

  1. Se observan dos tipos de errores diferentes en la entrega fallida, estos son:
  • status=deferred (lost connection with xx.xx.xx.xx[xx.xx.xx.xx] while sending end of data — message may be sent more than once)
  • status=deferred (lost connection with xx.xx.xx.xx[xx.xx.xx.xx] while sending message body)

El primero error se repite para los correos 1, 3, 4 y 5.

El segundo error aparece para el correo 2.

 

  1. La primer falla del correo ocurrió a las 11:32, hora en la que las capturas de paquetes de red aún no estaban activas por lo que este error no aparece reflejado en dichas capturas, sin embargo, el mismo error ocurrió en la entrega fallida de los últimos 3 correos por lo que el análisis tomará solamente el correo 5 para obtener la razón del error.
  2. La sexta línea indica que a partir de ese momento la entrega a la IP del balanceador se ha suspendido temporalmente por lo que estos correos no están siendo transmitidos en la red. Debido a esto no se espera ver paquetes de red donde se vea la transferencia de dicho correo. Este evento ocurrió a las 11:39:50. El correo con el que comienza este bloque tiene el identificador B727529008C y el error que muestra es:
  • status=deferred (delivery temporarily suspended: lost connection with xx.xx.xx.xx[xx.xx.xx.xx] while sending end of data — message may be sent more than once)
  1. La séptima y última línea sucedió 15 minutos después,  las 11:54:51. En esta ocasión se observa que la entrega hacia la IP del balanceador se ha vuelto a reintentar y en esta ocasión la entrega es satisfactoria. En este momento la comunicación entre el IMSVA y el balanceador se ha restablecido satisfactoriamente.

Lo que se observa en estas líneas es un comportamiento completamente normal y esperado por los equipos IMSVA ante problemas de red. Estos logs nos sirven para tener certeza de que IMSVA está operando correctamente lo que permite enfocar esfuerzos a otras áreas que pueden ser realmente la causa raíz del problema.

La interpretación correcta de la información anterior se muestra en los siguientes puntos:

  1. IMSVA utiliza como servidor de correo un Postfix interno, este componente tiene una configuración predeterminada para detectar problemas de red, así como los mecanismos para poder reaccionar ante ellos de acuerdo al RFC 2821 de SMTP.
  2. El motor de Postfix de IMSVA está configurado para detectar cuando la entrega de 5 correos consecutivos hacia una misma dirección IP ha fallado por problemas exclusivamente de conexión de red y no por errores de SMTP. El parámetro que controla este comportamiento es el siguiente, ubicado en el archivo main.cf de cada equipo IMSVA:

 

  • initial_destination_concurrency = 5

 

  1. En caso de que no se lleguen a completar las 5 fallas consecutivas por motivos de red el contador se regresa a su valor por defecto de “0” y comienza a contar nuevamente.
  2. Cuando el contador llega al valor configurado de “5” fallas por motivos de red se suspende temporalmente la entrega a esa IP en particular por 15 minutos, este valor está configurado por el siguiente parámetro de postfix:

 

  • minimal_backoff_time = 900s

 

  1. Se observa que apartir de este momento el retraso de los correos es de “0” segundos lo que indica que el correo no está siendo transmitido por la red sino que está siendo re-encolado inmediatamente. La línea que se muestra corresponde al sexto correo, es decir el siguiente correo después de que se complieron las 5 fallas seguidas.

 

  • delays=171519/456/0/0 Este parámetro indica un retraso de 0 segundos

El último punto para confirmar que el error no es provocado por el MTA interno es revisar los tres archivos maillog de cada servidor para confirmar que en la ventana de tiempo cuando ocurrió el error no existe ninguna caída del servicio de Postfix. Si podemos ver líneas en el log durante esta ventana significa que los tres servidores Postfix estaban arriba al momento de ocurrir la falla, por lo que necesariamente el problema debe estar en la red, ya sea el balanceador ó el equipo CISCO que se encuentran en el medio.

 

Análisis de las capturas de paquetes

Ya que se tienen identificados los 5 correos que no pudieron ser entregados por fallas en la red, se realizará el análisis de los paquetes de red correspondientes.

Correos 1, 3 y 4.

Como se explicó al inicio, no existen datos en la captura de paquetes para determinar el error presente en la falla del correo 1, por lo que se utilizará el correo 5 determinar este error. Ya se explicó que la hora de registro de la falla del correo 1 no está contemplada en la captura, sin embargo para los correos 3 y 4 sucede lo siguiente. En las líneas se muestra la hora en que el servidor IMSVA registró el evento y el retraso que ya presentaba el correo en ese instante:

Feb 28 11:37:27 imsva postfix/smtp[18259]: 08B8A23727E: to=<user@domain.com>, relay=xx.xx.xx.xx[xx.xx.xx.xx]:25, delay=239046, delays=238733/0.6/0/313, dsn=4.4.2, status=deferred (lost connection with xx.xx.xx.xx[xx.xx.xx.xx] while sending end of data — message may be sent more than once)

Feb 28 11:37:30 imsva postfix/smtp[18383]: DE006231956: to=<user@domain.com>, relay=xx.xx.xx.xx[xx.xx.xx.xx]:25, delay=165866, delays=165550/7.1/0/309, dsn=4.4.2, status=deferred (lost connection with xx.xx.xx.xx[xx.xx.xx.xx] while sending end of data — message may be sent more than once)

 

Para el correo 3 el evento fue escrito por el módulo de Postfix del servidor IMSVA a las 11:37:27, sin embargo, se puede ver también que ya habían pasado 5 minutos (313 segundos) mientras se intentaba mandar este correo hacia el balanceador. Por lo que la transferencia de correo tuvo que haber comenzado a las 11:32:14, sin embargo este horario no está contemplado dentro de los paquetes de red capturados. Lo mismo ocurre con el correo 4 que se registró tan sólo 3 segundos después y que presentaba un retraso de entrega también de más de 5 minutos (309 segundos). Por este motivo el análisis de estos correos no se incluye y la causa de la falla se determinará con el correo 5.

 

Correo 2

Debido a que las capturas de paquetes son muy grandes (más de 300MB) será muy difícil manejarlas en Wireshark por lo que primero partiremos el archivo .cap orginal en archivos más pequeños que contengan los rangos de tiempo que estamos buscando para el correo 2. Para segmentar el paquete orignal ejecutamos el siguiente comando desde un CMD y ubicándonos en la ruta donde tenemos instalado Wireshark en nuestra máquina Windows.

C:\Program Files\Wireshark>editcap.exe -c 10000 c:\capturas\captura.cap c:\capturas\captura_slice.cap

Después de ejecutado, este comando generará varios archivos utilizando como patrón de nombre “captura_slice” que serán más fáciles de manejar en Wireshark. Si después de ejecutado este comando los archivos no contienen los rangos de tiempo que estamos buscando se puede volver a ejecutar cambiando el valor de “10000” paquetes por alguno mayor o menor hasta que se obtenga un archivo que contenga los rangos completos.

Ya que tenemos un archivo más pequeño que se puede manipular en Wireshark y que contiene la ventana de tiempo de nuestro correo 2, aplicaremos el siguiente filtro para ubicar los paquetes de red que contienen la conversación SMTP con la que se transfirió el correo. Para esto aplicaremos el siguiente filtro en Wireshark donde “user@domain” es alguno de los buzones que aparecen como destinatarios en  este correo.

smtp.req.command eq RCPT and smtp.req.parameter contains “user@domain”

Como resultado de este filtro obtendremos una o varias líneas que contienen el comando SMTP RCPT TO:<user@domain.com>. Para estar seguros de que es la línea que buscamos configuraremos nuestro Wireshark para mostrar la hora en que cada paquete fue transmitido. En el menú View seleccione la opción “Time Display Format -> Time of Day”. Ahora verificamos que la hora del paquete en Wireshark coincida con la hora reflejada en el archivo maillog. Abra todos los archivos pequeños que se obtuvieron anteriormente hasta encontrar la línea que corresponde a este correo. Ya que se tiene la línea ubicada en el archivo correcto, haga click sobre la línea y seleccione la opción “Follow TCP stream…”.

Este correo tiene el identificador B93A62600D1 y va dirigido a tres destinatarios. La imagen que se muestra a continuación presenta la captura del correo saliendo del servidor IMSVA y siendo recibido a través del balanceador por el servidor interno Postfix.

dsn442_1

Algunos puntos a notar sobre esta captura:

  1. Es de notar que el banner está enmascarado con símbolos “*” lo que indica que hay un dispositivo CISCO en el medio aplicando un filtro sobre la conversación SMTP.
  2. Se observan los tres destinatarios que se registraron en el log de postfix.
  3. Se observa el identificador interno de postfix, lo que confirma que estamos observando el mismo correo.

Ahora se muestra el final de este correo:

dsn442_13

Puntos a notar sobre esta captura:

  1. Se observa claramente que el correo está incompleto ya que en el bloque mostrado se observa la transmisión de un archivo adjunto codificado en Base64, esto implica que este correo se está transmitiendo en formato MIME, y como tal debe terminar con esa sintaxis, misma que no aparece al final del correo. Además no se observa el comando de cierre del correo especificado por el RFC 2821, el cual es <CRLF>.<CRLF>.
  2. Tampoco se observa el comando QUIT ó RSET para identificar el fin de la transmisión del correo ni ningún código de respuesta de parte del servidor interno Postfix.
  3. Observe en el campo inferior de la imagen que la conversación SMTP pesa 53,616 bytes. Es decir, el servidor IMSVA transmitió satisfactoriamente esta cantidad de datos hacia el balanceador.

De esta captura sabemos a cuál de los tres servidores Postfix se entregó este correo así que abrimos la captura de paquetes correspondiente a ese servidor, le aplicamos el mismo procedimiento para generar archivos más pequeños y buscamos con el mismo filtro los paquetes que corresponden a la trasferencia del mismo correo.

Ahora veremos la captura que muestra cómo recibió este correo el servidor interno Postfix a través del balanceador.

dsn442_2

Puntos a notar sobre esta captura:

  1. En primer lugar vemos que el banner de saludo no está enmascarado lo que confirma que hay un equipo en el medio que está realizando modificaciones sobre los paquetes SMTP.
  2. Se confirma que vienen los 3 destinatarios originales tal y como aparecen en el correo que salió del servidor IMSVA.
  3. Como último punto confirmamos que se trata del mismo correo porque el identificador es el mismo registrado en el maillog  y el que aparece también en la captura de salida del servidor IMSVA.

Ahora mostramos el final de este correo tal y como lo recibió el servidor interno Postfix.

dsn442_14

Puntos a notar sobre esta captura:

  1. Es claro que este correo también está incompleto, sin embargo, a diferencia del correo que salió del servidor IMSVA, a este correo le faltan más paquetes. A diferencia del correo que salió del servidor IMSVA, aquí sólo recibimos 26,400 bytes.
  2. Se observa que a pesar de que el balanceador recibió exitosamente 53,616 bytes del servidor IMSVA, sólo retransmitió 26,400. Esto implica una pérdida de 27,216 bytes que nunca llegaron al servidor interno Postfix.

Ahora se presentan los últimos paquetes de red observados desde el servidor IMSVA al balanceador y del balanceador al servidor interno Postfix.

dsn442_3

Puntos a notar sobre esta captura:

  1. El último paquete que envía el servidor IMSVA al balanceador es un RST. De acuerdo al RFC 793 donde se define el protocolo TCP, el paquete RST es un mecanismo utilizado para que el cliente pueda cortar la comunicación con el servidor cuando ocurre un falla de sincronía en la conversación TCP.
  2. El penúltimo paquete recibido por el servidor IMSVA desde el balanceador es un ACK del paquete 52042, sin embargo el servidor IMSVA no estaba esperando ese paquete ya que el último enviado era el 49146. A continuación se muestra la lista de paquetes enviados por el servidor IMSVA a partir del comando DATA de SMTP con lo que se puede confirmar que el balanceador provocó una falla de sincronía en la comunicación al enviar un paquete no esperado.

Paquetes enviados desde IMSVA

202

1650

3098

4298

5746

7194

8394

11290

14186

15634

16586

19482

23826

28170

28874

31770

36114

40458

49146

 

Para comprobar la secuencia de paquetes, basta con seleccionar las líneas donde la IP destino corresponde a la de IMSVA , después seleccionamos el protocolo TCP y abrimos este paquete buscando los números de secuencia como se muestra en la siguiente imagen:

dsn442_4

 

  1. Al recibir un paquete no esperado, el servidor IMSVA reacciona como lo dicta el RFC de TCP y envía un paquete RST ya que el balanceador ha perdido la sincronía de la conversación.
  2. En el servidor IMSVA, la capa de TCP corta repentinamente la conexión con el balanceador por lo que la sesión de SMTP se encuentra repentinamente desconectada mientras estaba mandando el cuerpo del correo. Al no poder concluir con la transferencia satisfactoria y al no poder recibir respuesta del servidor interno Postfix, asume un error de red que justifica la acción de encolamiento de ese correo para su entrega posterior.
  3. Con esta captura se justifica el hecho de que aparezca el error específico “dsn=4.4.2” en este correo, ya que en efecto, la desconexión ocurrió mientras se transmitía el cuerpo del correo.
  • status=deferred (lost connection with xx.xx.xx.xx[xx.xx.xx.xx] while sending message body)

Conclusión.

La evidencia obtenida del servidor IMSVA y los paquetes de red que salieron de este equipo son congruentes al confirmar que hubo en efecto una falla de red provocada por el balanceador y por esta razón ese correo no pudo ser entregado. Esto confirma también que en este correo el servidor IMSVA no presentó falla alguna y se comportó de acuerdo a lo marcado por los estándares de TCP y SMTP.

 

Correo 5

Como se mencionó anteriormente, el análisis del error de este correo se utilizará también para determinar la causa del error de los correos 1, 3 y 4 ya que presentan el mismo comportamiento.

Feb 28 11:39:50 imsva postfix/smtp[18266]: C6C05235C9A: to=<user@domain.com>, relay=xx.xx.xx.xx[xx.xx.xx.xx]:25, delay=587488, delays=587032/145/0.01/311, dsn=4.4.2, status=deferred (lost connection with xx.xx.xx.xx[xx.xx.xx.xx] while sending end of data — message may be sent more than once)

Este correo fue registrado a las 11:39:50 cuando ya presentaba un retraso de más de 5 minutos (311 segundos) por lo que el inicio de la transferencia tuvo que haber ocurrido cerca de las 11:34:39, por lo que el evento sí se encuentra registrado y puede analizarse.

La siguiente imagen muestra el correo saliendo del servidor IMSVA hacia el balanceador y su equivalente al ser recibido del balanceador por el servidor interno Postfix. Recuerde aplicar el mismo procedimiento que usamos en el correo 2 para ubicar exactamente el mismo correo en las dos capturas de paquetes.

dsn442_15

Puntos a notar sobre esta captura:

  1. Al igual que con el correo 2 se pone en evidencia que existe un enmascaramiento de paquetes durante la transferencia del correo entre el servidor IMSVA y el servidor interno Postfix.
  2. También se confirma que el destinatario es el mismo en ambos correos y que también es el mismo que se registró en IMSVA.
  3. Finalmente se confirma que se trata del mismo correo registrado en el equipo IMSVA al mostrar exactamente el mismo identificador, lo que comprueba que se está analizando el mismo correo.

Ahora se presenta una parte de este correo para mostrar la forma en la que sale y en que es recibido.

dsn442_5

Puntos a notar en esta captura:

  1. En la parte superior podemos ver el identificador de una imagen que viene adjunta en el correo. Esto es sólo para tener una referencia objetiva de que se trata en efecto del mismo.
  2. A partir de aquí se observa claramente una modificación de los paquetes SMTP provocada por el equipo CISCO que se encuentra en el medio. Se observa que la línea que comienza con “De: Leticia” es recibido por el servidor interno Postfix (después de haber pasado por el balanceador y el equipo CISCO) como “XXX Leticia”.
  3. Así mismo, en el mismo recuadro se observa que después de la línea anterior seguía un espacio en blanco y la siguiente línea debería comenzar con “Enviado el:”, sin embargo el espacio en blanco no aparece en el correo recibido por el servidor interno Postfix, lo que indica una modificación intrusiva por parte de los equipos de red en este correo. Así mismo se vuelve a confirmar que todas las líneas comienzan ahora con caracteres enmascarados “XXX”.

Ahora se presenta el final del correo para apreciar el cierre de los datos con el comando <CRLF>.<CRLF>.

dsn442_16

Puntos a notar en esta captura:

  1. En primer lugar observamos que el total de bytes transmitidos por el servidor IMSVA y los recibidos por el servidor interno Postfix son idénticos: 90,169 bytes lo que comprueba que los dos equipos transmitieron y recibieron exitosamente el total del contenido del correo a través de la red.
  2. En segundo lugar observamos que cuando se manda el comando para cerrar el correo ó el final de los datos (“end of data”), el comando es modificado por los dispositivos de red, cambiando el caracter “.” por “X”, esto provoca que el servidor interno Postfix piense que aún no se ha terminado la transferencia del correo y mantiene la sesión abierta. Por esta razón el servidor IMSVA se queda esperando la respuesta de aceptación del correo sin obtenerla.

El RFC 2821 tiene prevista esta situación y ofrece un mecanismo a los SMTP Clients para que en caso de no recibir una respuesta al comando de cierre del correo, puedan asumir que existe un error de red y así justifiquen el hecho de encolar el correo para su entrega posterior. Esto es con la intención de no mantener la sesión abierta por tiempo ilimitado.

Lo anterior es congruente con el error que se está recibiendo cuando la entrega de este correo falla:

while sending end of data

El módulo de Postfix de los equipos IMSVA controla este timeout a través del siguiente parámetro que por defecto tiene un valor de 5 minutos:

smtp_quit_timeout = 300s

Lo que estamos viendo en esta captura es nuevamente un comportamiento normal de los equipos IMSVA. Al no haber recibido la respuesta esperada al comando <CRLF>.<CRLF> por parte del servidor interno después de 5 minutos, el servidor IMSVA asume que existe un error en la conexión de red que evita que la respuesta le llegue, al pasar los 5 minutos, el servidor IMSVA está en la libertad de cerrar la sesión, justificando el encolamiento del correo con el error “dsn=4.4.2” que vemos en las líneas del maillog.

A continuación se presenta la imagen de los paquetes donde se aprecia el cierre del correo:

dsn442_8

Puntos a notar en esta captura:

  1. Estos son los últimos paquetes de la conversación SMTP. Del lado izquierdo se aprecia el paquete que sale del servidor IMSVA hacia el balanceador y a la derecha se ve el equivalente que viene del balanceador hacia el servidor interno Postfix.
  2. Se puede observar que entre los dos paquetes enmarcados existe una diferencia de 10 segundos. El primer paquete contiene la primer porción del comando de cierre del correo que corresponde a un <CRLF> y la segunda, la que viene 10 segundos después contiene el resto .<CRLF>. Este comportamiento es consistente en todos los correos que se transfieren entre ambos servidores y lo que indica es que el motor de Postfix de IMSVA ha detectado que existe un equipo que está aplicando filtros a la conversación de SMTP. Esto lo determina al recibir el saludo “220 ****”.
  3. Este tipo de enmascaramiento puede provocar inconsistencia en la interpretación de la conversación SMTP. En concreto se sabe que uno de los problemas ocurre porque el comando <CRLF>.<CRLF> se modifica de tal forma que no puede ser interpretado por el servidor que recibe el correo. El módulo de Postfix cuenta, por diseño, con un parámetro que le permite tratar de mitigar esta situación al mandar el comando por separado y con una diferencia de 10 segundos entre uno y otro. Sin embargo, la documentación de Postfix es muy clara al especificar que este parámetro no asegura la corrección del problema y que lo mejor sería eliminar ese tipo de enmascaramiento en los equipos que lo provocan. El parámetro que controla este comportamiento es el siguiente:

 

  • smtp_pix_workaround_delay_time = 10s

Este punto en particular refleja que los equipos IMSVA están conscientes de que existe un equipo que está enmascarando paquetes SMTP y trata de aplicar el parámetro de Postfix para evitar que la conversación se corrompa, sin embargo, como hemos comprobado, la modificación de paquetes que hacen los equipos de red va más allá de modificar sólo este comando.

La siguiente imagen muestra los paquetes exactos del comando <CRLF>.<CRLF> antes y después del balanceador y el equipo CISCO.

dsn442_9

Puntos a notar en esta captura:

  1. El comando <CRLF>.<CRLF> en ASCII corresponde a la secuencia hexadecimal “0D0A 2E 0D0A”. La conversión correspondiente de <CRLF>X<CRLF> es “0D0A 58 0D0A”
  2. En la captura de la izquierda observamos que el servidor IMSVA envía en dos partes el comando de cierre del correo. Este comportamiento se explicó anteriormente como normal ya que Postfix ha detectado un dispositivo que está enmascarando la conversación SMTP por lo que ambos paquetes llevan una diferencia de 10 segundos. El primero lleva la porción “<CRLF>” y el segundo el resto “.<CRLF>”.
  3. En la captura de la derecha se observa la versión modificada por el balanceador y el equipo CISCO donde es evidente que el comando que el servidor interno Postfix está esperando es modificado por <CRLF>X<CRLF>. Por esta razón el servidor Postfix sigue en espera del cierre de datos por parte del servidor IMSVA.
  4. Finalmente es de notar que el primer paquete con el comando <CRLF> que recibe el servidor interno Postfix contiene como caracteres previos únicamente “X” por lo que vuelve a comprobarse que en efecto hubo una modificación intrusiva por parte del equipo CISCO.

Finalmente presentamos la imagen del paquete RST que se envió para cerrar la conexión TCP para la falla de correos 3, 4 y 5. Cabe aclarar que estos son los únicos paquetes RST que se enviaron desde el servidor IMSVA hacia el balanceador lo que es congruente con todo el análisis presentado, además de mostrar la misma hora en que fueron registrados los eventos en el log del servidor IMSVA. Esta captura se obtuvo utilizando el siguiente filtro de Wireshark donde buscamos únicamente paquetes con flag RESET en “1”.

tcp.flags.reset eq 1

dsn442_7

 

Conclusión.

En base a la evidencia obtenida de los logs del servidor I y las capturas de red presentadas se confirma que los equipos IMSVA no presentaron ningún problema al procesar estos correos. También se confirma que el retraso presentado por dichos correos fue por un comportamiento normal de los equipos IMSVA ante la presencia de problemas de red, respuestas que están apegadas al estándar RFC 2821 de SMTP. Así mismo se comprueba nuevamente que las fallas de red fueron provocadas por una modificación hecha por el balanceador y/o el equipo CISCO sobre la conversación SMTP. Cabe aclarar que en este análisis no se emite ninguna recomendación de modificaciones sobre la red ya que dichos cambios son responsabilidad del área de comunicaciones.

 

Nuestro análisis termina aquí y en nuestro caso enviamos nuestro reporte a las áreas correspondientes para que se encargaran de hacer el análisis y corrección de los equipos de red involucrados, pero nunca lo hicieron :(. Al menos nostros dejamos documentado nuestro trabajo y demostramos con un análisis certero y objetivo que tanto nuestros servicios como la implementación de IMSVA estuvierona a la altura de personal experto en seguridad de correo.

 

Para mayor información sobre el funcionamiento y las reglas del correo electrónico te recomendamos Fundamentos de Correo Electrónico.

Para mayor información sobre IMSVA, su instalación, implementación, configuración y funcionamiento te recomendamos nuestro libro Manual Avanzado de Implementación y Configuración de IMSVA. También puedes visitar nuestra sección de Libros y nuestra sección de IMSVA para información complementaria.

Recuerda que puedes mandarnos tus preguntas y comentarios a nuestra cuenta de Twitter: @redinskala donde podrás encontrar más información y tips de seguridad.

One thought on “Análisis de pérdida de conexión en IMSVA (dsn=4.4.2)

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

Comments are closed.