{"id":234,"date":"2014-06-20T16:39:03","date_gmt":"2014-06-20T15:39:03","guid":{"rendered":"http:\/\/www.alvaromarin.com\/?p=234"},"modified":"2014-06-20T16:39:03","modified_gmt":"2014-06-20T15:39:03","slug":"desaparicion-de-mensajes-en-postfix","status":"publish","type":"post","link":"http:\/\/www.alvaromarin.com\/2014\/06\/20\/desaparicion-de-mensajes-en-postfix\/","title":{"rendered":"Desaparici\u00f3n de mensajes en Postfix"},"content":{"rendered":"

He tenido dudas a la hora de poner un t\u00edtulo a este post. El concepto \u00abdesaparici\u00f3n\u00bb puede que sea algo amarillista<\/em>, quiz\u00e1s \u00abp\u00e9rdida de rastro de mensajes\u00bb pudiese hacer m\u00e1s justicia a lo que voy a comentar, pero bueno, queda m\u00e1s \u00abExpediente X\u00bb el actual ;-)<\/p>\n

Todo esto viene debido a que buscando en los logs un determinado mensaje enviado, no se sab\u00eda (a priori) qu\u00e9 hab\u00eda pasado con \u00e9l. 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. <\/p>\n

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<\/em> de Postfix a MailScanner, como sucede con otras pasarelas de correo como amavids-new<\/em>, sino que cuando llegan los mensajes v\u00eda SMTP, pasan a la cola hold<\/em> donde quedan retenidos y MailScanner, con un proceso batch<\/em>, procede a recogerlos de ah\u00ed regularmente para analizarlos.<\/p>\n

<\/p>\n

Obviamente, no es lo m\u00e1s limpio pero funciona bastante bien, de hecho, funciona. Pero cuando el log de correo mostraba para un mensaje que hab\u00eda sido enviado, esto:<\/p>\n


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

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<\/p>\n

Jun 16 19:47:48 postfix\/cleanup[28517]: 18A2F23A00A: message-id=<003901cf898b$1307a000$3916e000$@domain.com><\/code><\/p>\n

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

Los logs posteriores de MailScanner o Postfix, no muestran nada relativo a este mensaje (Expendiente X).<\/p>\n

Sin embargo, si nos fijamos m\u00e1s adelante en el log y buscamos con el PID del proceso smtpd<\/em> que recibe la conexi\u00f3n, nos encontramos con:<\/p>\n

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

Jun 16 19:49:16 postfix\/smtpd[1736]: disconnect from x.staticIP.rima-tde.net[IP]
\n<\/code><\/p>\n

es decir, hubo un error en la conexi\u00f3n SMTP que estaba enviando el mensaje y dio timeout<\/em>. Esto explica lo que pas\u00f3 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\u00f3n telnet<\/em>…hacer la conexi\u00f3n al servidor y cuando est\u00e9s escribiendo el cuerpo del mensaje, en la secci\u00f3n data<\/em>, hacer un Control-AltGr-]<\/em> para abortar la sesi\u00f3n y veremos que pasa lo indicado.<\/p>\n

Pero deja algunas preguntas…\u00bfPor qu\u00e9 no hay un mensaje relacionado con ese timeout<\/em> en base al ID? \u00bfPor qu\u00e9 asigna un ID a un mensaje que no ha llegado totalmente?<\/p>\n

Viktor Dukhovni hablaba de ello hace tiempo en la lista:<\/p>\n

The \u00abHOLD\u00bb action in body_checks and header_checks happens as the message
\nis being accumulatd to the queue file, before the entire message is
\nreceived (i.e. before the final \u00ab.\u00bb that terminates the message)
\nand before the \u00ab250 OK\u00bb is sent to the remote server.
\nFor transactions that abort in the middle of message transmission, you
\nmay see cleanup prepare to \u00abHOLD\u00bb the message, but the full message
\nnever arrives and so the queue file is deleted.<\/em><\/p>\n

Algo que tiene sentido pero que deja sin respuesta a la primera pregunta, por qu\u00e9 no asociar el mensaje de error de timeout<\/em> al ID de cola.<\/p>\n

Tras proponerselo, comentaba un posible parche que lo solucionaba:<\/p>\n

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

Pero Wietse Venema no estaba convencido de ello:<\/p>\n

Such logging is desirable with mail that Postfix has taken
\nresponsibility for, but it’s not compelling in the case of thrash,
\nand there is no guarantee that it would always be logged because
\na Postfix daemon may be terminated prematurely. <\/em><\/p>\n

as\u00ed que as\u00ed se queda el asunto. <\/p>\n

No ser\u00e9 yo quien le lleve la contraria al bueno de Wietse, pero sigo pensando que ser\u00eda deseable relacionar el error con el ID del mensaje (pensando, por ejemplo, en scripts<\/em> y aplicaciones de trazado de mensajes). <\/p>\n

Habr\u00e1 que tener todo esto en cuenta cuando se presente de nuevo alg\u00fan caso parecido.<\/p>\n","protected":false},"excerpt":{"rendered":"

He tenido dudas a la hora de poner un t\u00edtulo a este post. El concepto \u00abdesaparici\u00f3n\u00bb puede que sea algo amarillista, quiz\u00e1s \u00abp\u00e9rdida de rastro de mensajes\u00bb pudiese hacer m\u00e1s justicia a lo que voy a comentar, pero bueno, queda … Sigue leyendo →<\/span><\/a><\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":[],"categories":[5],"tags":[],"yoast_head":"\nDesaparici\u00f3n de mensajes en Postfix - www.alvaromarin.com<\/title>\n<meta name=\"robots\" content=\"index, follow, max-snippet:-1, max-image-preview:large, max-video-preview:-1\" \/>\n<link rel=\"canonical\" href=\"https:\/\/www.alvaromarin.com\/2014\/06\/20\/desaparicion-de-mensajes-en-postfix\/\" \/>\n<meta property=\"og:locale\" content=\"es_ES\" \/>\n<meta property=\"og:type\" content=\"article\" \/>\n<meta property=\"og:title\" content=\"Desaparici\u00f3n de mensajes en Postfix - www.alvaromarin.com\" \/>\n<meta property=\"og:description\" content=\"He tenido dudas a la hora de poner un t\u00edtulo a este post. El concepto \u00abdesaparici\u00f3n\u00bb puede que sea algo amarillista, quiz\u00e1s \u00abp\u00e9rdida de rastro de mensajes\u00bb pudiese hacer m\u00e1s justicia a lo que voy a comentar, pero bueno, queda … Sigue leyendo →\" \/>\n<meta property=\"og:url\" content=\"https:\/\/www.alvaromarin.com\/2014\/06\/20\/desaparicion-de-mensajes-en-postfix\/\" \/>\n<meta property=\"og:site_name\" content=\"www.alvaromarin.com\" \/>\n<meta property=\"article:published_time\" content=\"2014-06-20T15:39:03+00:00\" \/>\n<meta name=\"author\" content=\"Alvaro Mar\u00edn Illera\" \/>\n<meta name=\"twitter:label1\" content=\"Escrito por\" \/>\n\t<meta name=\"twitter:data1\" content=\"Alvaro Mar\u00edn Illera\" \/>\n\t<meta name=\"twitter:label2\" content=\"Tiempo de lectura\" \/>\n\t<meta name=\"twitter:data2\" content=\"4 minutos\" \/>\n<script type=\"application\/ld+json\" class=\"yoast-schema-graph\">{\"@context\":\"https:\/\/schema.org\",\"@graph\":[{\"@type\":\"WebPage\",\"@id\":\"https:\/\/www.alvaromarin.com\/2014\/06\/20\/desaparicion-de-mensajes-en-postfix\/\",\"url\":\"https:\/\/www.alvaromarin.com\/2014\/06\/20\/desaparicion-de-mensajes-en-postfix\/\",\"name\":\"Desaparici\u00f3n de mensajes en Postfix - www.alvaromarin.com\",\"isPartOf\":{\"@id\":\"http:\/\/www.alvaromarin.com\/#website\"},\"datePublished\":\"2014-06-20T15:39:03+00:00\",\"dateModified\":\"2014-06-20T15:39:03+00:00\",\"author\":{\"@id\":\"http:\/\/www.alvaromarin.com\/#\/schema\/person\/287057c6a545a612badd5caa00bfd0bf\"},\"breadcrumb\":{\"@id\":\"https:\/\/www.alvaromarin.com\/2014\/06\/20\/desaparicion-de-mensajes-en-postfix\/#breadcrumb\"},\"inLanguage\":\"es\",\"potentialAction\":[{\"@type\":\"ReadAction\",\"target\":[\"https:\/\/www.alvaromarin.com\/2014\/06\/20\/desaparicion-de-mensajes-en-postfix\/\"]}]},{\"@type\":\"BreadcrumbList\",\"@id\":\"https:\/\/www.alvaromarin.com\/2014\/06\/20\/desaparicion-de-mensajes-en-postfix\/#breadcrumb\",\"itemListElement\":[{\"@type\":\"ListItem\",\"position\":1,\"name\":\"Portada\",\"item\":\"http:\/\/www.alvaromarin.com\/\"},{\"@type\":\"ListItem\",\"position\":2,\"name\":\"Desaparici\u00f3n de mensajes en Postfix\"}]},{\"@type\":\"WebSite\",\"@id\":\"http:\/\/www.alvaromarin.com\/#website\",\"url\":\"http:\/\/www.alvaromarin.com\/\",\"name\":\"www.alvaromarin.com\",\"description\":\"Blog sobre spam, sistemas antispam y correo electr\u00f3nico\",\"potentialAction\":[{\"@type\":\"SearchAction\",\"target\":{\"@type\":\"EntryPoint\",\"urlTemplate\":\"http:\/\/www.alvaromarin.com\/?s={search_term_string}\"},\"query-input\":\"required name=search_term_string\"}],\"inLanguage\":\"es\"},{\"@type\":\"Person\",\"@id\":\"http:\/\/www.alvaromarin.com\/#\/schema\/person\/287057c6a545a612badd5caa00bfd0bf\",\"name\":\"Alvaro Mar\u00edn Illera\",\"image\":{\"@type\":\"ImageObject\",\"inLanguage\":\"es\",\"@id\":\"http:\/\/www.alvaromarin.com\/#\/schema\/person\/image\/\",\"url\":\"http:\/\/1.gravatar.com\/avatar\/d260aa4421f4ceb816fe98ba240bec2b?s=96&d=mm&r=g\",\"contentUrl\":\"http:\/\/1.gravatar.com\/avatar\/d260aa4421f4ceb816fe98ba240bec2b?s=96&d=mm&r=g\",\"caption\":\"Alvaro Mar\u00edn Illera\"},\"url\":\"http:\/\/www.alvaromarin.com\/author\/admin\/\"}]}<\/script>\n<!-- \/ Yoast SEO plugin. -->","yoast_head_json":{"title":"Desaparici\u00f3n de mensajes en Postfix - www.alvaromarin.com","robots":{"index":"index","follow":"follow","max-snippet":"max-snippet:-1","max-image-preview":"max-image-preview:large","max-video-preview":"max-video-preview:-1"},"canonical":"https:\/\/www.alvaromarin.com\/2014\/06\/20\/desaparicion-de-mensajes-en-postfix\/","og_locale":"es_ES","og_type":"article","og_title":"Desaparici\u00f3n de mensajes en Postfix - www.alvaromarin.com","og_description":"He tenido dudas a la hora de poner un t\u00edtulo a este post. El concepto \u00abdesaparici\u00f3n\u00bb puede que sea algo amarillista, quiz\u00e1s \u00abp\u00e9rdida de rastro de mensajes\u00bb pudiese hacer m\u00e1s justicia a lo que voy a comentar, pero bueno, queda … Sigue leyendo →","og_url":"https:\/\/www.alvaromarin.com\/2014\/06\/20\/desaparicion-de-mensajes-en-postfix\/","og_site_name":"www.alvaromarin.com","article_published_time":"2014-06-20T15:39:03+00:00","author":"Alvaro Mar\u00edn Illera","twitter_misc":{"Escrito por":"Alvaro Mar\u00edn Illera","Tiempo de lectura":"4 minutos"},"schema":{"@context":"https:\/\/schema.org","@graph":[{"@type":"WebPage","@id":"https:\/\/www.alvaromarin.com\/2014\/06\/20\/desaparicion-de-mensajes-en-postfix\/","url":"https:\/\/www.alvaromarin.com\/2014\/06\/20\/desaparicion-de-mensajes-en-postfix\/","name":"Desaparici\u00f3n de mensajes en Postfix - www.alvaromarin.com","isPartOf":{"@id":"http:\/\/www.alvaromarin.com\/#website"},"datePublished":"2014-06-20T15:39:03+00:00","dateModified":"2014-06-20T15:39:03+00:00","author":{"@id":"http:\/\/www.alvaromarin.com\/#\/schema\/person\/287057c6a545a612badd5caa00bfd0bf"},"breadcrumb":{"@id":"https:\/\/www.alvaromarin.com\/2014\/06\/20\/desaparicion-de-mensajes-en-postfix\/#breadcrumb"},"inLanguage":"es","potentialAction":[{"@type":"ReadAction","target":["https:\/\/www.alvaromarin.com\/2014\/06\/20\/desaparicion-de-mensajes-en-postfix\/"]}]},{"@type":"BreadcrumbList","@id":"https:\/\/www.alvaromarin.com\/2014\/06\/20\/desaparicion-de-mensajes-en-postfix\/#breadcrumb","itemListElement":[{"@type":"ListItem","position":1,"name":"Portada","item":"http:\/\/www.alvaromarin.com\/"},{"@type":"ListItem","position":2,"name":"Desaparici\u00f3n de mensajes en Postfix"}]},{"@type":"WebSite","@id":"http:\/\/www.alvaromarin.com\/#website","url":"http:\/\/www.alvaromarin.com\/","name":"www.alvaromarin.com","description":"Blog sobre spam, sistemas antispam y correo electr\u00f3nico","potentialAction":[{"@type":"SearchAction","target":{"@type":"EntryPoint","urlTemplate":"http:\/\/www.alvaromarin.com\/?s={search_term_string}"},"query-input":"required name=search_term_string"}],"inLanguage":"es"},{"@type":"Person","@id":"http:\/\/www.alvaromarin.com\/#\/schema\/person\/287057c6a545a612badd5caa00bfd0bf","name":"Alvaro Mar\u00edn Illera","image":{"@type":"ImageObject","inLanguage":"es","@id":"http:\/\/www.alvaromarin.com\/#\/schema\/person\/image\/","url":"http:\/\/1.gravatar.com\/avatar\/d260aa4421f4ceb816fe98ba240bec2b?s=96&d=mm&r=g","contentUrl":"http:\/\/1.gravatar.com\/avatar\/d260aa4421f4ceb816fe98ba240bec2b?s=96&d=mm&r=g","caption":"Alvaro Mar\u00edn Illera"},"url":"http:\/\/www.alvaromarin.com\/author\/admin\/"}]}},"_links":{"self":[{"href":"http:\/\/www.alvaromarin.com\/wp-json\/wp\/v2\/posts\/234"}],"collection":[{"href":"http:\/\/www.alvaromarin.com\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"http:\/\/www.alvaromarin.com\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"http:\/\/www.alvaromarin.com\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"http:\/\/www.alvaromarin.com\/wp-json\/wp\/v2\/comments?post=234"}],"version-history":[{"count":4,"href":"http:\/\/www.alvaromarin.com\/wp-json\/wp\/v2\/posts\/234\/revisions"}],"predecessor-version":[{"id":238,"href":"http:\/\/www.alvaromarin.com\/wp-json\/wp\/v2\/posts\/234\/revisions\/238"}],"wp:attachment":[{"href":"http:\/\/www.alvaromarin.com\/wp-json\/wp\/v2\/media?parent=234"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/www.alvaromarin.com\/wp-json\/wp\/v2\/categories?post=234"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/www.alvaromarin.com\/wp-json\/wp\/v2\/tags?post=234"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}