IMSVA retraso en la entrega de correo (cleanup muy alto)

En este artículo mostramos la metodología para diagnosticar un problema reportado en el que el servidor IMSVA provoca un retraso de entre 5 y hasta 15 minutos en la entrega del correo. Este servidor IMSVA sólo recibe correo de Internet y lo manda a un servidor de correo Interno.

El primer paso para identificar el problema es buscar un correo que haya llegado retrasado para buscar las líneas correspondientes que nos indiquen cuál puede ser la causa del problema. Una vez que tenemos el correo vemos los encabezados para sacar el identificador interno de Postfix y así poder buscarlo en las líneas del maillog:

Received: from imsva (unknown [127.0.0.1] by IMSVA (Postfix) with ESMTP id 03F662083B; Wed, 20 Mar 2013 14:14:18 -0400 (CST)

Ya que tenemos los encabezados buscamos la línea en que el scanner de IMSVA manda el correo hacia el Postfix de entrega, esta línea se ubica fácilmente porque aparece la línea unknown [127.0.0.1] by IMSVA (Postfix). Aquí podemos ver el parámetro “id” que contiene el identificador de Postfix (03F662083B en este ejemplo).

Ahora entramos al IMSVA vía shell y buscamos el identificador en el archivo maillog con el siguiente comando:

# cat /var/log/maillog |grep 03F662083B

Si no aparece ningún resultado, entonces puede ser que ese correo ya no se encuentre en ese maillog, así que lo buscamos en los otros 4 maillogs así:

# cat /var/log/maillog.1 |grep “03F662083B”

# cat /var/log/maillog.2 |grep “03F662083B”

# cat /var/log/maillog.3 |grep “03F662083B”

# cat /var/log/maillog.4 |grep “03F662083B”

Cuando lo encontremos analizamos la línea, a continuación se presenta el resultado que obtuvimos nostros:

Mar 20 14:19:12 imsva4 postfix/smtp[29121]: 03F662083B: to=<user@domain.com>, relay=xx.xx.xx.xx[xx.xx.xx.xx]:25, conn_use=4, delay=895, delays=0.63/893/0.01/0.44, dsn=2.5.0, status=sent (250 2.5.0 Ok, envelope id 0MJZ003W97xxx)

En esta línea vemos tres cosas importantes. La primera es el parámetro “delay” que indica un retraso en la entrega de este correo de 895 segundos (14.9 minutos), la segunda es que el demonio de Postfix “cleanup” tardó 893 segundos en limpiar este correo y finalmente observamos que el correo sí se entregó satisfactoriamente (satus=sent).

El parámetro delays nos indica el tiempo que los demonios smtpd, cleanup, qmgr y smtp han tardado en procesar este correo. Lo que estamos viendo aquí, es que el demonio cleanup tardó demasiado en terminar de limpiar el correo. Este demonio se encarga de hacer la limpieza del correo de acuerdo al RFC 822 de SMTP, esta limpieza incluye agregar los encabezados que hacen falta, quitar espacios en blanco, líneas en blanco y corregir los buzones para que aparezcan como “<buzón>” en vez de sólo “buzón”.

Generalmente este proceso no debe tardar más de algunos milisegundos así que debe haber algo que está retrasando esta tarea más de lo normal. Para averiguarlo, sacaremos algunas estadísticas del maillog para entender qué es lo que ha estado procesando el servidor y cuanto correo le está llegando.

Los siguientes filtros se aplicarán en todos los archivos maillog para tener una idea del comportamiento global de IMSVA:

Primero sacamos el número de conexiones que se están recibiendo con el siguiente comando:

# cat maillog|grep ” connect from”|grep -v 127.0.0.1|wc –l

Observe que antes de la palabra “connect” hay un espacio para evitar que aparezcan las líneas “disconnect” y que al final estamos excluyendo todas las líneas donde aparece la IP local porque esas líneas son las del scanner y no cuentan como conexiones externas.

En nuestro caso vemos que el número total de conexiones en un rango de 10 horas es de más de 300,000 conexiones, específicamente en el rango de tiempo donde ocurrió el retraso del correo que estamos analizando hubo cerca de 80,000 conexiones en dos horas.

Ahora buscamos errores que puedan estar provocando encolamiento en el servidor IMSVA, para esto aplicamos el siguiente filtro

# cat maillog|grep “dsn=4”|wc –l

En nuestro caso observamos que el resultado es de más de 50,000 correos en la misma ventana donde ocurrió el retraso del correo que estamos analizando. Ahora vemos que de estos 50,000 se presentan los siguientes errores:

warning: lots of deferred mail, that is bad for performance

warning: 63F4220289: queue file size limit exceeded (este error aparece casi 40,000 veces)

451 4.2.1 mailbox temporarily disabled:

451 4.2.2 user over quota; cannot receive new mail

dsn=4.4.1, status=deferred (connect to localhost[127.0.0.1]:10025: Connection refused)

dsn=4.4.2, status=deferred (lost connection with localhost[127.0.0.1] while receiving the initial server greeting)

 

Con esta información ya tenemos una idea de cuál es el problema:

En los horarios de 10-12 y 12-14hrs. se reciben 70,030 y 76,573 correos respectivamente:

Problema: Esta cantidad de correo está provocando que la cola de entrega (active) se llene periódicamente (entre 2 y 5 veces) en cada horario. En esta situación el proceso de movimiento de correos se detiene y se provoca un encolamiento al no poder procesar más correo.

Solución: Hay que modificar la siguiente línea del archivo /opt/trend/imss/postfix/etc/postfix/main.cf para aumentar la cantidad de correo que se puede encolar en la entrega:

 

qmgr_message_recipient_limit = 20000

por

qmgr_message_recipient_limit = 50000

 

En todos los horarios se observa una gran cantidad de correos que no pueden ser entregados por que los usuarios tienen lleno su buzón (user over quota; cannot receive new mail).

Problema: IMSVA tendrá que encolar estos correos por 24 horas antes de desecharlos. Esto provoca que la cola de active se sature periódicamente y se provoque lentitud en la entrega de correos nuevos y viejos.

Solución: Se recomienda disminuir el tiempo que los correos pueden permanecer encolados en IMSVA para que se liberen recursos más rápido. Para esto se debe modificar la siguiente línea del archivo main.cf:

 

maximal_queue_lifetime = 1d

por

maximal_queue_lifetime = 6h

 

Con esta modificación, los correos se estarán eliminando cuatro veces al día en vez de 1, esto porque de todas formas esos correos no podrán ser entregados hasta que los usuarios liberen espacio en sus buzones.

 

Se observa una gran cantidad conexiones (la más alta es de 30000) en bloques de dos horas.

Problema: Una gran cantidad de conexiones simultáneas podría dejar sin conexiones disponibles al servidor para aceptar nuevo correo.

Solución: tomando el número más alto y sacando un promedio por segundo, se observa que se tienen en promedio 4 conexiones simultáneas. IMSVA está configurado para aceptar 200 conexiones simultaneas por lo que no debería causar ningún problema de performance, sin embargo, se sugiere que se aumente a 1024 para tener un número de conexiones disponibles mayor. Este cambio se realiza desde la consola web (Administration -> SMTP Routing -> Connections (Allow up to 1024 connections).

 

Después de aplicados estos cambios hemos resuelto el problema de retraso y nuestro servidor IMSVA está soportando sin problemas la carga de correo a pesar de ser muy alta. Esperamos que esta metodología sea de utilidad para diagnosticar éste y otro tipo de problemas de retraso y encolamiento en IMSVA (Postfix).

 

Para mayor información sobre la creación y 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 encontrarás más información y tips de seguridad.