He tenido dudas a la hora de poner un título a este post. El concepto «desaparición» puede que sea algo amarillista, quizás «pérdida de rastro de mensajes» pudiese hacer más justicia a lo que voy a comentar, pero bueno, queda más «Expediente X» el actual ;-)

Todo esto viene debido a que buscando en los logs un determinado mensaje enviado, no se sabía (a priori) qué había pasado con él. Esto es lo que creo (y supongo que todo el mundo cree) que no debe hacer un log, no dejar evidencias de lo que pasa.

Juntar MailScanner con Postfix siempre ha sido muy criticado, sobre todo en la lista de usuarios de Postfix. No hay una interfaz que pase los mensajes recibidos en el demonio smtpd de Postfix a MailScanner, como sucede con otras pasarelas de correo como amavids-new, sino que cuando llegan los mensajes vía SMTP, pasan a la cola hold donde quedan retenidos y MailScanner, con un proceso batch, procede a recogerlos de ahí regularmente para analizarlos.

Obviamente, no es lo más limpio pero funciona bastante bien, de hecho, funciona. Pero cuando el log de correo mostraba para un mensaje que había sido enviado, esto:


Jun 16 19:47:48 postfix/smtpd[1736]: 18A2F23A00A: client=x.staticIP.rima-tde.net[IP],sasl_method=LOGIN, sasl_username=user@domain.com

Jun 16 19:47:48 postfix/cleanup[28517]: 18A2F23A00A: hold: header Received: from x(x[IP]) by relayserver (Postfix) with ESMTPA id from x[x]; from=user@domain.com to=user2@domain.com proto=ESMTP helo=PC

Jun 16 19:47:48 postfix/cleanup[28517]: 18A2F23A00A: message-id=

y solo esto, algo olía mal. Como se ve en ese extracto de log, el usuario se autentica vía SMTP AUTH, al mensaje se le asigna un ID de cola (18A2F23A00A) y entra en la cola hold. Posteriormente, se le asigna un message-id.

Los logs posteriores de MailScanner o Postfix, no muestran nada relativo a este mensaje (Expendiente X).

Sin embargo, si nos fijamos más adelante en el log y buscamos con el PID del proceso smtpd que recibe la conexión, nos encontramos con:

Jun 16 19:49:16 postfix/smtpd[1736]: timeout after DATA (1184351 bytes) from x.staticIP.rima-tde.net[IP]

Jun 16 19:49:16 postfix/smtpd[1736]: disconnect from x.staticIP.rima-tde.net[IP]

es decir, hubo un error en la conexión SMTP que estaba enviando el mensaje y dio timeout. Esto explica lo que pasó y exime a MailScanner de ser el causante de algo relacionado con todo esto. De hecho, es algo que se puede reproducir con una simple conexión telnet…hacer la conexión al servidor y cuando estés escribiendo el cuerpo del mensaje, en la sección data, hacer un Control-AltGr-] para abortar la sesión y veremos que pasa lo indicado.

Pero deja algunas preguntas…¿Por qué no hay un mensaje relacionado con ese timeout en base al ID? ¿Por qué asigna un ID a un mensaje que no ha llegado totalmente?

Viktor Dukhovni hablaba de ello hace tiempo en la lista:

The «HOLD» action in body_checks and header_checks happens as the message
is being accumulatd to the queue file, before the entire message is
received (i.e. before the final «.» that terminates the message)
and before the «250 OK» is sent to the remote server.
For transactions that abort in the middle of message transmission, you
may see cleanup prepare to «HOLD» the message, but the full message
never arrives and so the queue file is deleted.

Algo que tiene sentido pero que deja sin respuesta a la primera pregunta, por qué no asociar el mensaje de error de timeout al ID de cola.

Tras proponerselo, comentaba un posible parche que lo solucionaba:

--- a/postfix/src/smtpd/smtpd.c
+++ b/postfix/src/smtpd/smtpd.c
@@ -4893,13 +4893,15 @@ static void smtpd_proto(SMTPD_STATE *state)
*/
if (state->reason && state->where) {
if (strcmp(state->where, SMTPD_AFTER_DATA) == 0) {
- msg_info("%s after %s (%lu bytes) from %s", /* 2.5 compat */
+ msg_info("%s: %s after %s (%lu bytes) from %s", /* 2.5 compat */
+ (state->queue_id ? state->queue_id : "NOQUEUE"),
state->reason, SMTPD_CMD_DATA, /* 2.5 compat */
(long) (state->act_size + vstream_peek(state->client)),
state->namaddr);
} else if (strcmp(state->where, SMTPD_AFTER_DOT)
|| strcmp(state->reason, REASON_LOST_CONNECTION)) {
- msg_info("%s after %s from %s",
+ msg_info("%s: %s after %s from %s",
+ (state->queue_id ? state->queue_id : "NOQUEUE"),
state->reason, state->where, state->namaddr);
}
}


Pero Wietse Venema no estaba convencido de ello:

Such logging is desirable with mail that Postfix has taken
responsibility for, but it’s not compelling in the case of thrash,
and there is no guarantee that it would always be logged because
a Postfix daemon may be terminated prematurely.

así que así se queda el asunto.

No seré yo quien le lleve la contraria al bueno de Wietse, pero sigo pensando que sería deseable relacionar el error con el ID del mensaje (pensando, por ejemplo, en scripts y aplicaciones de trazado de mensajes).

Habrá que tener todo esto en cuenta cuando se presente de nuevo algún caso parecido.