Analizar logs básicos de correo entrante y saliente en servidores Postfix

Se analizará de forma breve los logs básicos de correo entrante y saliente en servidores Postfix para facilitar su interpretación.

Enlaces de interés.

• http://www.escomposlinux.org/lfs-es/blfs-es-SVN/server/postfix.html
• http://www.redinskala.com/2012/10/29/interpretacion-de-maillog-en-postfix/

Ejemplo de log de correo entrante en Postfix.

Jun 30 08:06:23 zenaida postfix/smtpd[7062]: connect from gateway.startcom.org[212.117.158.94]
Jun 30 08:06:24 zenaida postfix/smtpd[7062]: 56B621E1234: client=gateway.startcom.org[212.117.158.94]
Jun 30 08:06:24 zenaida postfix/smtpd[7062]: lost connection after RCPT from gateway.startcom.org[212.117.158.94]
Jun 30 08:06:24 zenaida postfix/smtpd[7062]: disconnect from gateway.startcom.org[212.117.158.94]

Jun 30 08:06:36 zenaida postfix/smtpd[7062]: connect from mta1.startcom.org[192.116.242.7]
Jun 30 08:06:37 zenaida postfix/smtpd[7062]: BA5141E1234: client=mta1.startcom.org[192.116.242.7]
Jun 30 08:06:38 zenaida postfix/cleanup[7067]: BA5141E1234: message-id=<aa65fc76340e8fedeca6502ce8c36b34@startcom.org>
Jun 30 08:06:38 zenaida postfix/qmgr[7052]: BA5141E1234: from=<certmaster@startcom.org>, size=1463, nrcpt=1 (queue active)
Jun 30 08:06:38 zenaida postfix/local[7068]: BA5141E1234: to=<webmaster@busindre.com>, relay=local, delay=0.52, delays=0.52/0/0/0, dsn=2.0.0, status=sent (delivered to mailbox)
Jun 30 08:06:38 zenaida postfix/qmgr[7052]: BA5141E1234: removed
Jun 30 08:06:38 zenaida postfix/smtpd[7062]: disconnect from mta1.startcom.org[192.116.242.7]

Dominio y dirección IP del servidor que conecta con el servidor de correo.

Jun 30 08:06:23 zenaida postfix/smtpd[7062]: connect from gateway.startcom.org[212.117.158.94]

Postfix recibe el primer comando RCPT TO exitosamente por parte del servidor y desconecta.

Jun 30 08:06:24 zenaida postfix/smtpd[7062]: 56B621E1234: client=gateway.startcom.org[212.117.158.94]
Jun 30 08:06:24 zenaida postfix/smtpd[7062]: lost connection after RCPT from gateway.startcom.org[212.117.158.94]
Jun 30 08:06:24 zenaida postfix/smtpd[7062]: disconnect from gateway.startcom.org[212.117.158.94]

Vuelve a conectar, esta vez desde otra IP, encargada de dejarnos el correo electrónico.

Jun 30 08:06:36 zenaida postfix/smtpd[7062]: connect from mta1.startcom.org[192.116.242.7]
Jun 30 08:06:37 zenaida postfix/smtpd[7062]: BA5141E1234: client=mta1.startcom.org[192.116.242.7]

El correo ha sido recibido con éxito por el demonio “smtpd”, el cual lo entrega a al demonio “cleanup” para corregir la sintaxis (RFC 822).

Jun 30 08:06:38 zenaida postfix/cleanup[7067]: BA5141E1234: message-id=<aa65fc76340e8fedeca6502ce8c36b34@startcom.org>

Se asume que la corrección fue terminada y se pasa la responsabilidad del demonio “qmgr”, los campos que contiene el log son estos.

• Remitente.
• Número de destinatarios.
• Tamaño del correo.
• Cola a la que se ha desplazado (active).

Jun 30 08:06:38 zenaida postfix/qmgr[7052]: BA5141E1234: from=<certmaster@startcom.org>, size=1463, nrcpt=1 (queue active)

NOTA: Cualquier correo en la cola “active” se considera como listo para ser entregado a su destino final, ya sea entrante o saliente.

Cuando Postfix encuentra en algún buzón el dominio que tiene configurado como propio en la variable $mydestination se le otorga al demonio “local”.

• Buzón real que recibe el correo, el buzón que se utilizó en el sobre del correo.
• Tipo de relay utilizado (local).
• El delay indica los tiempos que cada demonio tardó en procesar el correo (smtpd, cleanup, qmgr, local).
• El campo status muestra cuál fue el resultado de la operación.

Jun 30 08:06:38 zenaida postfix/local[7068]: BA5141E1234: to=<webmaster@busindre.com>, relay=local, delay=0.52, delays=0.52/0/0/0, dsn=2.0.0, status=sent (delivered to mailbox)

El demonio “qmgr” elimina el correo de la cola active ya que fue enviado satisfactoriamente y ya no es necesario conservarlo.

Jun 30 08:06:38 zenaida postfix/qmgr[7052]: BA5141E1234: removed

Ejemplo de log de correo saliente en Postfix.

Oct 14 16:23:35 debian postfix/pickup[9757]: 2CBE420A2F: uid=0 from=<root>
Oct 14 16:23:35 debian postfix/cleanup[10284]: 2CBE420A2F: message-id=<20141014142335.2CBE420A2F@debian>
Oct 14 16:23:35 debian postfix/qmgr[8572]: 2CBE420A2F: from=<root@debian>, size=331, nrcpt=1 (queue active)
Oct 14 16:23:35 debian postfix/smtp[10287]: 2CBE420A2F: to=<usuario@dominio.com>, relay=mail.dominio.com[211.63.85.21]:25, delay=0.11, delays=0.04/0/0/0.07, dsn=2.0.0, status=sent (250 OK id=1Xe30h-0000lo-0f)
Oct 14 16:23:35 debian postfix/qmgr[8572]: 2CBE420A2F: removed

Pickup es un demonio que espera señales para saber si el correo nuevo ha sido eliminado del directorio “maildrop” y se lo entrega al demonio “cleanup”, este procesa el correo entrante, lo inserta en la cola de correo entrante e informa al administrador de colas de su llegada.

Oct 14 16:23:35 debian postfix/pickup[9757]: 2CBE420A2F: uid=0 from=<root>
Oct 14 16:23:35 debian postfix/cleanup[10284]: 2CBE420A2F: message-id=<20141014142335.2CBE420A2F@debian>

Al igual que con el correo entrante, se corrige la sintaxis (RFC 822), se le continuidad con el demonio “qmgr”.

• Remitente.
• Número de destinatarios.
• Tamaño del correo.
• La cola en la que es colocado (active).

Oct 14 16:23:35 debian postfix/qmgr[8572]: 2CBE420A2F: from=<root@debian>, size=331, nrcpt=1 (queue active)

El demonio “smtp” es el encargado de la entrega de correo.

• Buzones de los destinatarios.
• El campo “relay” indica los datos del servidor y puerto a través del cuál se entregó el correo
• El “delay” indica el tiempo que tardó el correo desde que entró a Postfix y 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 del servidor SMTP al recibir nuestro correo. Una respuesta “250 OK” dada por el receptor suele incluir un ID (250 OK id=1Xe30h-0000lo-0f) que es utilizado por el receptor para trabajar con el correo. Gmail por ejemplo ofrece además del ID otro tipo de información: (250 2.0.0 OK 1485284631 v129si19330627wma.58 - gsmtp)

Oct 14 16:23:35 debian postfix/smtp[10287]: 2CBE420A2F: to=<usuario@dominio.com>, relay=mail.dominio.com[211.63.85.21]:25, delay=0.11, delays=0.04/0/0/0.07, dsn=2.0.0, status=sent (250 OK id=1Xe30h-0000lo-0f)

Al igual que en la entrega de correo, esta linea indica que el correo fue enviado satisfactoriamente y Postfix ya no necesita almacenar el correo. El demonio “qmgr” se encarga de eliminar la copia del correo original de la cola de “active”.

Jun 30 08:06:38 zenaida postfix/qmgr[7052]: BA5141E1234: removed

Ejemplo de salida cuando no se pudo entregar el correo (Queued mail for delivery).

postfix/smtp[56296]: 612972209C5: to=<blabla@dominio.com>, relay=112.61.81.26[112.61.81.26]:25, delay=0.18, delays=0.01/0/0/0.17, dsn=2.6.0, status=sent (250 2.6.0 <20121216162340.612971209C5@otrodominio.com> Queued mail for delivery)

A continuación se muestra una lista de códigos de error temporales SMTP de respuesta y lo que significan.

• 421 - <domain> Service not available, closing transmission channel.
• 450 - Requested mail action not taken: Mailbox unavailable.
• 451 - Requested action aborted: Local error in processing.
• 452 - Requested action not taken: Insufficient system storage.

Si el servidor de correo de recepción devuelve cualquiera de los códigos anteriores, los logs de postfix mostrarán el texto “Queued mail for delivery / En cola para la entrega”.