Interpretación de maillog en Postfix

[Read this post in English]

 

Los logs que genera Postfix se almacenan en un archivo llamado maillog que generalmente se encuentra ubicado en la ruta /var/log. La configuración de los eventos y la ubicación del archivo se controlan con los parámetros del archivo /etc/syslog con las siguientes líneas:

# Log all the mail messages in one place.
mail.* -/var/log/maillog

El nivel de información que se registra en este archivo se controla mediante los parámetros “-v” (verbose), “-vv” (very verbose), “-vvv” (very very verbose) en el archivo master.cf. Por defecto el nivel viene con la configuración más baja, si fuera necesario aumentar el detalle de los logs se pueden agregar los parámetros anteriores en el archivo master.cf cambiando la siguiente línea:

# ==========================================================================
# service type private unpriv chroot wakeup maxproc command + args
# (yes) (yes) (yes) (never) (100)
# ==========================================================================
smtp inet n – n – – smtpd -v

Después de modificar el master.cf es necesario reiniciar todo el postfix con “postfix restart” (en versiones más recientes) o con “postfix stop” y “postfix start” (en versiones anteriores). Después del reinicio podemos verificar que en el archivo maillog se registra ahora más detalle de las transacciones que realiza postfix. Aumentar este detalle solo se recomienda en situaciones donde hay un problema que no puede identificarse fácilmente, generalmente el nivel predeterminado es suficiente para identificar cualquier problema por lo que no es necesario tener a Postfix con los parámetros “-v” por mucho tiempo y mucho menos en una operación en producción.

La interpretación del log de Postfix es muy fácil de leer cuando se tienen identificadas las secciones que se quieren revisar. A continuación indicaremos la forma correcta de identificar cada sección del log y los filtros que podemos aplicar para ubicar información mucho más rápido.

La sintaxis general del log

La siguiente línea representa el formato básico en que se presenta la información del archivo maillog de Postfix:

Jan 2 11:15:39 tmims8201 postfix/smtpd[17397]: connect from unknown[127.0.0.1]

Como vemos, la primer sección nos indica únicamente la fecha y hora en que se registró el evento. En sistemas de correo en producción es necesario que la hora se encuentre bien sincronizada, ya que un fallo en este punto, puede generar que discrepancias en la información que estamos viendo en el log.

Jan 2 11:15:39 tmcent01 postfix/smtpd[17397]: connect from unknown[127.0.0.1]

El siguiente campo indica el nombre del servidor que está registrando el evento, en este caso es nuestro propio servidor Postfix.

Jan 2 11:15:39 tmcent01 postfix/smtpd[17397]: connect from unknown[127.0.0.1]

El siguiente campo es uno de los más críticos cuando estamos revisando algún problema en Postfix. Aquí se muestra el servicio / proceso [PID] que estaba en ejecución cuando se registró el evento. Esta información puede servir mucho para distinguir cada una de las partes que están involucradas al recibir, enviar o procesar el correo dentro de Postfix. Por ejemplo, de la línea anterior podemos deducir que el demonio en ejecución es “smtpd” que es el demonio que usa Postfix para recibir correo, por lo que el registro que estamos viendo es de un correo entrante y adicional tenemos el PID del demonio que recibió el correo. Ese mismo PID lo podemos utilizar para buscar en el log todas las operaciones que realizó con el correo.

Jan 2 11:15:39 tmims8201 postfix/smtpd[17397]: connect from unknown[127.0.0.1]

Finalmente, el último campo es simplemente la descripción del evento registrado. Aquí podremos ver códigos de status / error o descripciones textuales para su interpretación.

Con esta información podemos identificar fácilmente cada uno de los pasos por los que pasa el correo cuando es recibido, procesado y enviado a través de Postfix. Ahora analicemos con más detalle cada una de las secciones y bloques del log.

Secciones del maillog

A continuación se muestra el estracto del maillog cuando recibe un correo electrónico nuevo:

Logs de correo entrante

1. Jan 2 20:31:02 tmcent01 postfix/smtpd[26524]: connect from unknown[192.168.75.1]
2. Jan 2 20:31:12 tmcent01 postfix/smtpd[26524]: B58C4330038: client=unknown[192.168.75.1]
3. Jan 2 20:31:17 tmcent01 postfix/cleanup[27426]: B58C4330038: message-id=<20120103023112.B58C4330038@tmcent01.training5.tm>
4. Jan 2 20:31:17 tmcent01 postfix/qmgr[26454]: B58C4330038: from=<asdf@asdf.com>, size=711, nrcpt=1 (queue active)
5. Jan 2 20:31:17 tmcent01 postfix/local[27450]: B58C4330038: to=<root@tmcent01.training5.tm>, orig_to=<postmaster>, relay=local, delay=9.7, delays=9.6/0.03/0/0.02, dsn=2.0.0, status=sent (delivered to mailbox)
6. Jan 2 20:31:17 tmcent01 postfix/qmgr[26454]: B58C4330038: removed

La sección comprendida entre las líneas 1 y 2 son las que corresponden a la recepción del correo por Postfix. La línea 1 graba el nombre del servidor y su dirección IP entre corchetes, tomando en cuenta que lal mayoría de las veces veremos el hostname como unknown cuando el DNS de postfix no puede resolver su nombre. La línea 2 se registra en el momento en que Postfix recibe el primer comando RCPT TO de forma satisfactoria. La forma en que identificamos que en esta sección el correo se está recibiendo es porque el demonio registrado es el “smtpd” que es el demonio de recepción de Postfix.

La línea 3 indica que el correo ha sido recibido satisfactoriamente por el demonio “smtpd” y ahora el correo es responsabilidad del demonio “cleanup” que se encarga de corregir cualquier error de sintaxis en la estructura del correo electrónico que no corresponda con las reglas del RFC 822. Este tipo de correcciones incluyen entre otras las siguientes:

Si el buzón no viene entre los símbolos “<” y “>” se le agregan. Por ejemplo: user@domain.com se cambia por <user@domain.com>.

Si el correo electrónico no contiene el encabezado “Return-Path”, se lo agrega utilizando como valor el buzón del comando MAIL FROM.

Si el correo electrónico no contiene el encabezado “Date”, se lo agrega utilizando su propia fecha y hora.

Si el correo electrónico no contiene el encabezado “Message-ID”, genera uno completamente nuevo con sus propios datos.

Si los buzones del remitente y destinatarios no contienen un dominio, lo completa con la variable $myorigin.

La línea 4 asume que la corrección del correo contra el RFC 822 fue satisfactoria y ahora el correo es responsablidad del demonio “qmgr”. Este se encarga de mover a los correos a la cola adecuada dentro de Postfix. Cuando el correo ha sido corregido, la cola a la que se entrega es “active”. Cualquier correo en esta cola se considera como listo para ser entregado a su destino final. En la línea podemos ver el buzón del remitente del correo, el número de destinatarios, el tamaño total del correo y la cola a la que se está moviendo.

En la línea 5 vemos que el demonio en ejecución es el de “local”, este demonio se utiliza cuando Postfix encuentra en el buzón del destinatario el dominio que tiene configurado como propio en la variable $mydestination. Esta línea se genera cuando el demonio ya ha intentado enviar el correo y nos refleja el resultado de dicha operación. En nuestro ejemplo, indica el buzón real al que se está enviando el correo, el buzón que se utilizó en el sobre del correo, el tipo de relay utilizado (local significa que se trata de un correo interno), delays indica los tiempos que cada demonio tardó en procesar el correo (aquí vemos 4 valores que corresponden a los 4 demonios involucrados: smtpd, cleanup, qmgr, local), el campo dsn indica la respuesta que nos dió el SMTP Server al enviarle el correo y finalmente el campo de status muestra cuál fue el resultado de la operación. Esta información nos puede indicar tanto el envío correcto al buzón al destinatario o cualquier otro tipo de falla que se pudo haber generado en la transacción.

La línea 6 indica que ya que el correo fue enviado satisfactoriamente, ya no es necesario conservar el correo original dentro de Postfix por lo que el demonio “qmgr” se encarga de eliminar la copia que se encuentra en la cola de “active”. En este punto se puede asumir que el proceso de recepción del correo fue completamente satisfactorio.

Ahora analizaremos las líneas de log cuando Postfix entrega correo a dominios externos.
Logs de correo saliente

1. Jan 2 20:28:55 tmcent01 postfix/smtp[26597]: 1ED09330038: to=<administrator@training.tm>, relay=192.168.75.5[192.168.75.5]:25, delay=9.4, delays=9.2/0.02/0.02/0.2, dsn=2.6.0, status=sent (250 2.6.0 <20120103022852.1ED09330038@tmcent01.training5.tm> Queued mail for delivery)
2. Jan 2 20:28:55 tmcent01 postfix/qmgr[26454]: 1ED09330038: removed

En la entrega de correo sólo se tienen dos líneas.

La línea 1 corresponde al demonio “smtp” que es el que utiliza Postfix para la entrega de correo. Aquí veremos todos los datos y estado de la transacción. En primer lugar veremos los buzones de los destinatarios. El campo “relay” indica los datos del servidor y puerto a través del cuál se entregó el correo, su sintaxis es hostname[IP]:puerto. El campo delay indica el tiempo que tardó el correo desde que entró a Postfix y hasta que fue entregado a su destino. El campo “dsn” indica el código extendido con que respondió el SMTP Server ante el envío del correo. El campo “status” muestra la descripción y respuesta completa que dió el SMTP Server al recibir nuestro correo.

La línea 2 confirma que el correo fue enviado satisfactoriamente a todos los destinatarios por lo que Postfix ya no necesita almacenar el correo. El demonio “qmgr” se encarga de eliminar la copia del correo original de la cola de “active”.

Con esta información podemos comprobar la entrega exitosa del correo electrónico.

En base a lo descrito anteriormente veremos ahora la forma de efectuar algunos filtros para ayudarnos a identificar de una forma más eficiente información relevante de nuestro maillog.

Filtrando el archivo maillog

En esta sección veremos algunos filtros que podrán ayudarnos a contar con información más compacta y específica del archivo maillog.

Identificar todas las conexiones hechas en Postfix.

Para identificar todas las direcciones IP que se han conectado a nuestro servidor Postfix ejecutamos uno o todos los siguientes comandos:

cat /var/log/maillog | grep ” connect from ”

Como resultado de este comando veremos una lista completa de todas las líneas que contienen la IP de los servidores que se han conectado a nuestro servidor Postfix.

cat /var/log/maillog | grep ” connect from ” | wc -l

La salida de este comando nos dará el número de conexiones que se han realizado en nuestro servidor.

Los dos comandos anteriores nos darán el número total de conexiones que se han registrado en nuestro servidor Postfix, sin embargo, aquí también pueden encontrarse conexiones de algún servidor interno o algún servicio / appliance de anti-spam del cuál no queremos contabilizar sus conexiones. En este caso debemos excluir estas líneas usando el siguiente comando:

cat /var/log/maillog | grep ” connect from ” |grep -v 192.168.75.5

Este comando nos dará el listado de todas las líneas del maillog con los registros de las direcciones IP que se han conectado a Postfix excepto las líneas que contengan la IP 192.168.75.5.

cat /var/log/maillog | grep ” connect from ” |grep -v 127.0.0.1 |grep 192.168.75.5

Este comando tiene el mismo resultado solo que además de excluir las líneas con la IP 192.168.75.5 también excluye las líneas que contengan la dirección 127.0.0.1.

cat /var/log/maillog |grep ” connect from “|grep -v 192.168.75.5|wc -l

La salida de este comando nos da el número de líneas con un valor numérico en vez de la lista de las líneas completas.

Identificar el correo entrante en el maillog de Postfix

Para encontrar únicamente los correos entrantes en Postfix en el maillog, nos podemos servir de los siguientes comandos:

cat /var/log/maillog |grep “relay=local” |grep “status=sent”

Este comando nos regresa todas las líneas del maillog donde están los registros de correos entrantes que fueron entregados de forma local. Si agregamos el parámetro “|wc -l” al final obtendremos el número de las líneas en vez del listado.

cat /var/log/maillog |grep “relay=192.168.75.5” |grep “status=sent”

Si nuestro postfix entrega el correo interno a otro servidor de correo podemos filtrar por la dirección IP a la que le estamos entregano el correo. En este ejemplo el valor “192.168.75.5” representa el nombre con que se definió el servidor al que se entrega el correo, este valor puede ser una IP o el nombre del servidor de correo, tenga cuidado de cambiar este valor por el correspondiente en su Organización. Nuevamente, si usamos el parámetro “|wc -l” al final del comando obtendremos el número de las líneas y no el listado completo.

Identificar el correo saliente en el maillog de Postfix

Para encontrar únicamente los correos salientes en el maillog de Postfix, utilizamos el mismo comando para filtrar el correo entrante sólo que excluiremos los registros del correo interno como se muestra a continuación:

cat /var/log/maillog |grep -v “relay=local” |grep “relay=” |grep “status=sent”

Con este comando obtenemos el listado de todos los correos salientes que fueron entregados satisfactoriamente fuera de la organización. Si agregamos el parámetro “|wc -l” al final del comando obtenemos sólo el valor numérico en vez del listado completo de las líneas como se ha mostrado anteriormente.

cat /var/log/maillog |grep -v “relay=192.168.75.5” |grep “relay=” |grep “status=sent”

Si nuestro postfix entrega el correo interno a otro servidor, utilizamos este filtro para excluir las líneas donde se registra la entrega del correo interno a ese MTA. Tome en cuenta que deberá cambiar el valor de “192.168.75.5” por el correspondiente a su servidor interno de correo que puede ser una dirección IP o un FQDN. Al igual que en los casos anteriores, podemos usar el parámetro “wc -l” al final del comando para obtener un valor numérico en vez del listado de líneas.

Identificar el correo que no pudo ser entregado por Postfix

Los siguientes comandos se pueden utilizar para identificar errores en la entrega de correo ya sea por errores propios de Postfix o por problemas con los SMTP Servers externos.

cat /var/log/maillog |grep -v “status=sent” |grep “relay=”

La salida de este comando nos dará todas las líneas del archivo maillog donde se registró algún fallo en la entrega de correo ya sea interno o externo.

cat /var/log/maillog |grep -v “status=sent” |grep “relay=” |wc -l

Nos da el mismo resultado pero en valor numérico en vez del listado completo.

cat /var/log/maillog |grep -v “status=sent” |grep “relay=local”

Con este comando obtenemos todos los registros del maillog de Postfix en que aparecen las líneas con errores en la entrega de correo entrante únicamente.

cat /var/log/maillog |grep -v “status=sent” |grep “relay=local” |grep wc -l

Obtenemos el mismo resultado del comando anterior pero con valor numérico en vez del listado.

cat /var/log/maillog |grep -v “status=sent” |grep -v “realy=local” |grep “relay=”

Con este comando obtenemos el listado de todos los correos salientes que no pudieron ser entregados satisfactoriamente.

cat /var/log/maillog |grep -v “status=sent” |grep -v “relay=local” |grep “relay=” |wc -l

Obtenemos el mismo resultado que el filtro anterior pero con valor numérico en vez del listado completo.

cat /var/log/maillog |grep -v “status=sent” |grep -v “relay=192.168.75.5” |grep “relay=”

Si el servidor Postfix entrega su correo interno a otro servidor dentro de la organización podemos utilizar este filtro para excluir el correo interno sustituyendo el valor “192.168.75.5” por la IP o el FQDN del servidor de correo interno.

cat /var/log/maillog |grep -v “status=sent” |grep -v “relay=192.168.75.5” |grep “relay=” |wc -l

Este comando obtiene el mismo resultado que el filtro anterior pero en valor numérico en vez del listado completo.

Obtener el número de veces en que se ha recargado la configuración de Postfix

Este filtro se utiliza para saber las veces o el momento en que la configuración de postfix se ha vuelto a cargar. Este tipo de reinicios, al ser sólo de configuración, no implican que el servicio de correo se haya detenido.

cat /var/log/maillog |grep “reload”

Este comando nos dará el listado completo de todos los registros en que aparece un reinicio de la configuración del archivo main.cf de Postfix. Este listado puede servir para identificar la fecha y hora en que el motor ha recargado su configuración ya sea de forma automática o manual.

cat /var/log/maillog |grep “reload” |wc -l

Este comando obtiene la misma salida del filtro anterior pero en forma numérica en vez de un listado.
Obtener el número de veces en que se ha reiniciado el motor de Postfix

Este filtro sirve para identificar las veces o el momento exacto en que el motor de Postfix se detuvo. Esto indica que el servicio de correo se detuvo por lo que no se recibieron más correos hasta que el motor se volvió a levantar.

cat /var/log/maillog |grep stopping

La salida de este comando nos da la lista de registros donde se muestra que el motor de Postfix se detuvo, por lo que la disponibilidad del servicio de correo se vió interrumplida.

cat /var/log/maillog |grep stopping |wc -l

Nos da el mismo resultado que el filtro anterior pero de forma numérica en vez de un listado.

cat /var/log/maillog |grep -e stopping -e starting

Este comando nos ayuda a identificar más fácilmente si hubo algún reinicio completo al buscar por las dos conidiciones, tanto por las líneas donde se detuvo el motor como por las líneas donde se inició. De esta forma podemos comparar las horas y verificar el tiempo en que nuestro servicio estuvo caído o incluso si ocurrió alguna falla en el motor. Por ejemplo si vemos dos líneas seguidas de “starting” significa que el motor se detuvo inesperadamente y se inició en automático o de forma manual en la fecha y hora de la segunda línea.
Limpiar regsitros del Maillog

En caso de necesitar limpiar los registros del archivo maillog de Postfix para efectuar alguna prueba ó por alguna tarea de mantenimiento, se puede aplicar el siguiente procedimiento de forma segura:

# > /var/log maillog

Este comando limpiará el archivo maillog y eliminará todos los registros dejándolo limpio para las subsecuentes pruebas. Este comando se puede ejecutar en línea sin necesidad de reiniciar Postfix para que tome efecto.

 

Poner el maillog en modo debug

El archivo maillog de Postfix se encarga de registrar todos los eventos relacionados con los demonios de Postfix, por lo que cuando se quiere un debug, el archivo no se pone realmente en debug, lo que se configura es la cantidad de información que cada demonio registra en el archivo. Para esto se debe saber con certeza qué demonio es el que se necesita que registre mayor información y con respecto a eso se configura el archivo master.cf para comenzar el debug. La siguiente es una recomendación sobre el debug de demonios para algunas situaciones más comunes:

  • smtpd. El debug de este demonio nos dará más detalle sobre todos los correos entrantes de Postfix.
  • smtp. El debug de este demonio nos dará más detalle sobre todos los correos salientes de Postfix.
  • cleanup. Aquí se nos dará más información sobre todas las operaciones de higiene que se realizan sobre el correo que se está procesando.
  • qmgr. Este demonio se encarga de mover el correo entre las diversas colas de Postfix.

El debug se habilita, agregando la línea “-v” al final de la línea del demonio correspondiente en el archivo /etc/postfix/master.cf. También se pueden usar “-vv” y “-vvv” cada uno aumentando el nivel de debug del demonio.

Ejemplo:

smtp      inet  n       –       n       –       200       smtpd -v

 

Modificar el comportamiento del maillog

En ocasiones es necesario incrementar la cantidad de información que se registra en el archivo /var/log/maillog, en estos casos se puede modificar el archivo /etc/logrotate.conf con los parámetros necesarios. Por default el maillog rota semanalmente o cuando un archivo alcanza los 10MB (10240k), la situación que ocurra primero. Si se quiere guardar información más allá de estos límites para tener registros de más días ó meses entonces se puede hacer una de las siguientes configuraciones en el archivo /etc/logrotate.conf

La primera opción es cambiar el comportamiento de TODOS los logs administrados por syslog, esta configuración es la primera que aparece en el archivo y afectará no sólo al maillog sino a todos los logs.

# rotate log files weekly
weekly
# keep 4 weeks worth of backlogs
rotate 4

El primer campo puede recibir los valores: daily, weekly, monthly y yearly. El campo “rotate” indica hasta cuantos archivos se pueden rotar, por default el maillog genera 4 archivos:

maillog -> El log actual

maillog.1, maillog.2, maillog.3 y maillog.4 que contienen la última información rotada.

La segunda opción es cambiar sólamente la configuración del maillog para no afectar a los demás logs y se tenga un aumento en el espacio ocupado en disco. Este método es el recomendado y para aplicarlo hay que ubicar la sección que corresponde al maillog, a continuación mostramos la sección original.

/var/log/maillog{
size 10240k
postrotate
/usr/bin/killall -HUP syslogd
endscript
}
Si queremos que este log genere 10 archivos con información pasada y que rote diariamente, podemos aplicar la siguiente configuración

/var/log/maillog{
   daily
   rotate 10  
   size 10240k
   postrotate
      /usr/bin/killall -HUP syslogd
  endscript
}

Esta configuración guardará la información de 10 días ó al menos la información que quepa en 10 archivos de 10MB, lo que suceda primero lo que da un total de un máximo de 100MB de información. Si esto no es suficiente se puede aumentar el numero de logs ajustando el parámetro “rotate” ó se puede aumentar el tamaño que pueden soportar los archivos, a continuación ponemos la configuración para guardar información que rota de forma semanal con 5 archivos y maneje un tamaño por archivo de 100MB. Esta configuración guardará un máximo de 500MB.

/var/log/maillog{
   daily
   rotate 10   
   size 102400k
   postrotate
      /usr/bin/killall -HUP syslogd
  endscript
}

Con esta configuración podrás ajustar la información registrada en este log ya sea incrementando ó disminuyendo la cantidad de datos por cada archivo.

 

Te recomendamos visitar nuestro artículo sobre Análisis del Archivo Maillog para Postfix e IMSVA (Parte I) donde mostramos cómo obtener indicadores más precisos para medir el performance de tu servidor.

Para mayor información sobre el funcionamiento del correo electrónico te recomendamos nuestro libro Fundamentos de Correo Electrónico.

Puedes enviarnos tus preguntas y comentarios también a través de nuestra cuenta de Twitter: @redinskala donde encontrarás mayor información y tips de seguridad.

 

3 thoughts on “Interpretación de maillog en Postfix

  1. Eres la neta del planeta amigo! la verdad pasé un montón de tiempo buscando información útil para poder interpretar correctamente los logs de Postfix hasta que encontré tu página, me has ayudado increiblemente Saludos desde México!

  2. Pingback: Postfix maillog interpretation | RedinSkala

Comments are closed.