====== 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/]]

===== Análisis del registro de correo entrante en Postfix =====

Ejemplo de log de correo entrante en Postfix.
<code>
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]
</code>

Dominio y dirección IP del servidor que conecta con el servidor de correo.
<code>Jun 30 08:06:23 zenaida postfix/smtpd[7062]: connect from gateway.startcom.org[212.117.158.94]</code>

Postfix recibe el primer comando RCPT TO exitosamente por parte del servidor y desconecta.
<code>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]</code>

Vuelve a conectar, esta vez desde otra IP, encargada de dejarnos el correo electrónico.
<code>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]</code>

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).
<code>Jun 30 08:06:38 zenaida postfix/cleanup[7067]: BA5141E1234: message-id=<aa65fc76340e8fedeca6502ce8c36b34@startcom.org></code>

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

El demonio "//qmgr//" elimina el correo de la cola active ya que fue enviado satisfactoriamente y ya no es necesario conservarlo.
<code>Jun 30 08:06:38 zenaida postfix/qmgr[7052]: BA5141E1234: removed</code>

===== Análisis del registro de correo saliente en Postfix =====
Ejemplo de log de correo saliente en Postfix.
<code>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</code>

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. 
<code>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></code>

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).
<code>Oct 14 16:23:35 debian postfix/qmgr[8572]: 2CBE420A2F: from=<root@debian>, size=331, nrcpt=1 (queue active)</code>

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)

<code>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)</code>

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//".
<code>Jun 30 08:06:38 zenaida postfix/qmgr[7052]: BA5141E1234: removed</code>

**Ejemplo de salida cuando no se pudo entregar el correo** (Queued mail for delivery).
<code>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)</code>

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".