[aviso: lineas mayores de 72 chars] El 2004-10-26 a las 10:21 +0200, Emiliano Sutil escribió:
Yo sospecharía de algún procesado posterior al postfix, tipo procmail. La respuesta se puede encontrar siempre mirando los logs cuidadosamente.
Pues he seguido tu consejo y me he puesto a mirar los logs detenidamente. aqui paso un fragmento y lo comento, porque creo que mi problema está relacionado con un error que pase hace unos dias de unos mensajes que me salian en los logs.
Oct 25 16:20:19 adslinux imapd: Connection, ip=[::ffff:192.168.1.132] Oct 25 16:20:19 adslinux amavis[5053]: (05053-09) Checking:
-> Oct 25 16:20:19 adslinux amavis[5053]: (05053-09) WARN: all primary virus scanners failed, considering backups
Esto es que le has dicho al amavis que mire los virus, pero no encuentra ningún programa antivirus. Es un aviso, simplemente no escaneará. Fíjate que el amavis tiene un identificador, "05053-09", que se ve posteriormente. Creo que identifica al proceso del amavis, no al correo, mirando en mis propios logs: porque el numero que sea se repite demasiado (en un intervalo de unos 20 minutos), y porque la primera parte (antes del guion) se corresponde con el PID del proceso. El 9 quizás sea el thread. Ahhh... mirando en mis logs, ese número va entre 1 y 10. Lo cual se corresponde con esto en /etc/amavisd.conf: $max_servers = 5; # number of pre-forked children (default 2) $max_requests = 10; # retire a child after that many accepts (default 10) Cuando un hijo del amavis ha procesado 10 correos, se le retira de la circulación - eufemismo, se le mata :-p ¡Interesante! Siempre se aprende algo nuevo ;-)
Oct 25 16:20:19 adslinux imapd: LOGIN, user=luis, ip=[::ffff:192.168.1.132], protocol=IMAP
Esto es, imagino, un usuario local que se ha conectado al servidor imapd. O más posiblemente, es el cliente de correo que está enviando que al mismo tiempo está cambiando cosas en la carpeta de enviados.
Oct 25 16:20:20 adslinux postfix/smtpd[5557]: connect from localhost[127.0.0.1] Oct 25 16:20:20 adslinux postfix/smtpd[5557]: 7712E31DB3: client=localhost[127.0.0.1]
Aquí tenemos un correo local con ID (de la cola) 7712E31DB3. El msgid (Message-ID) viene en la siquiente linea:
Oct 25 16:20:20 adslinux postfix/cleanup[5576]: 7712E31DB3: message-id=<044f01c4ba9c$2fecd050$8400000a@mag03>
Observa que por ese identificador puedes encontrar el correo en el buzón. Se garantiza que es único universalmente. Bueno, en la Tierra :-)
Oct 25 16:20:20 adslinux amavis[5053]: (05053-09) white_black_list: whitelisted sender
Oct 25 16:20:20 adslinux amavis[5053]: (05053-09) FWD via SMTP: [127.0.0.1]:10025 ->
El amavis (proceso anterior 05053-09) dice que el correo está limpio porque el originante está en la lista blanca, y se lo pasa al postfix de nuevo (FWD via SMTP).
Oct 25 16:20:20 adslinux postfix/smtpd[5575]: connect from localhost[127.0.0.1]
Esto es el postfix recibiendo desde el amavis, como acabo de decir.
Oct 25 16:20:20 adslinux postfix/smtpd[5575]: 99FF431DBE: client=localhost[127.0.0.1]
Y aquí tenemos el ID de la cola del postfix de este correo. Observa que al principio teniamos el "7712E31DB3", que por si hay dudas no es el mismo porque el PID del postfix/smtpd era "5557".
Oct 25 16:20:20 adslinux postfix/cleanup[5558]: 99FF431DBE: message-id=<417D0B0E.1010702@iranon.com>
El postfix le ha dado ese otro msgid - observa por tanto que tenemos con seguridad en este trozo de registro que has pasado dos correos totalmente independientes.
Oct 25 16:20:20 adslinux postfix/smtpd[5575]: disconnect from localhost[127.0.0.1]
Oct 25 16:20:20 adslinux amavis[5053]: (05053-09) Passed,
-> , Message-ID: <417D0B0E.1010702@iranon.com>, Hits: -
El amavis (el proceso 05053-09 de antes) sigue procesando el correo anterior, con msgid 417D0B0E.1010702@iranon.com. De hecho, creo que es el informe final de terminación, porque ese msgid ya lo hemos visto en el postfix/cleanup un par de lineas arriba, es decir, ya lo ha entregado.
Oct 25 16:20:20 adslinux postfix/qmgr[32128]: 99FF431DBE: from=
, size=1428, nrcpt=1 (queue active) Oct 25 16:20:20 adslinux amavis[5053]: (05053-09) TIMING [total 812 ms] - SMTP EHLO: 2 (0%), SMTP pre-MAIL: 0 (0%), SMTP pre-DATA-flush: 2 (0%), SMTP DATA: 39 (5%), body hash: 0 (0%), mime_decode: 10 (1%), AV-scan-1: 659 (81%), fwd-connect: 5 (1%), fwd-m
Informe definitivo de estadísticas de tiempo del amavis respecto a ese correo. Yo lo tengo desactivado, ocupa mucho y embrolla el registro.
Oct 25 16:20:20 adslinux postfix/smtp[5559]: CDD7331D8E: to=
, relay=localhost[127.0.0.1], delay=1, status=sent (250 2.6.0 Ok, id=05053-09, from MTA: 250 Ok: queued as 99FF431DBE)
El postfix encola el correo CDD7331D8E como 99FF431DBE, y entonces borra el CDD7331D8E (linea de abajo). Esto me confunde un poco, porque no veo el CDD7331D8E más arriba, y creo que debería estar.
Oct 25 16:20:20 adslinux postfix/qmgr[32128]: CDD7331D8E: removed Oct 25 16:20:20 adslinux postfix/qmgr[32128]: warning: premature end-of-input on private/smtp socket while reading input attribute name
Y ya tenemos el problema gordo: el proceso que está borrando el fichero de cola CDD7331D8E se queja que se le ha muerto prematuramente la entrada. Raro.
Oct 25 16:20:20 adslinux postfix/qmgr[32128]: warning: private/smtp socket: malformed response Oct 25 16:20:20 adslinux postfix/qmgr[32128]: warning: transport smtp failure -- see a previous warning/fatal/panic logfile record for the problem description Oct 25 16:20:20 adslinux postfix/master[32123]: warning: process /usr/lib/postfix/smtp pid 5573 killed by signal 11
Y el postix reacciona matando un proceso smtp (5573), que no se ha visto antes. Tendrías que buscar en tu log que es lo que estaba haciendo ese PID algo más arriba, porque ibamos por el 5575.
Oct 25 16:20:20 adslinux postfix/cleanup[5558]: C077F31DBC: message-id=<20041025142020.C077F31DBC@adslinux.iranon.com> Oct 25 16:20:20 adslinux postfix/qmgr[32128]: C077F31DBC: from=<>, size=3165, nrcpt=1 (queue active) Oct 25 16:20:20 adslinux postfix/local[5578]: C077F31DBC: to=
, relay=local, delay=0, status=sent (delivered to maildir)
Este último párrafo me lia. Tenemos un msgid que no ha salido antes (incluso el dominio es distinto, "adslinux."). Y lo entrega localmente. Me falta un cacho de log para verlo bien. ¿Ves como hago el proceso? Con mucha calma y un café ;-)
Si os fijais todo parece normal hasta que llega el proceso qmgr[32128] que da un error. Para mi que al dar ese error no se borra de la cola y vuelve a intentar enviarlo. Otra linea del log que me preocupa es esta: WARN: all primary virus scanners failed, considering backups
Esto lo da el amavis y no se si tendrá algo que ver.
Creo que no.
Veis algo mas extraño que puede influir? y alguna accion correctora? porque la verdad a mi no se me ocurre nada de nada.
De momento, no... busca ese PID que mata, el 5573, a ver que es lo que estaba haciendo. Si dicen que pasa desde que pusiste imap, a ver si toca algo de eso. ¿Que usas, la versión que viene con el suse 9.1? Puedes actualizar a la version de ftp...people/choeger También puedes aumentar momentaneamente el grado de explicitez del log: #debug_peer_list = some.domain -- Saludos Carlos Robinson