Antes de nada, agradecerte el tiempo que te has tomado en detallarme lo que ha pasado en el log, habia un montón de cosas que no me habia dado cuenta. Vamos allá. Carlos E. R. wrote:
[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á.
Cuando has dicho esto me he dicho ahi te has colado Carlos, pero no exactamente. Yo tengo instalado como antivirus el clamav y me funciona de maravilla, me pilla un montonazo de correos con virus pero lo que veo cuando arranca el amavis es esto: Oct 26 16:10:06 adslinux amavis[26229]: Found secondary av scanner Clam Antivirus - clamscan at /usr/bin/clamscan Es decir el clamav lo trata como secundario mientras que el mensaje habla de primarios, lo que no se es como se indica cuales son primarios y cuales secundarios.
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 ;-)
Pues si muy interesante, de hecho voy a empezar a hacer pruebas sobre el efecto en el rendimiento.
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.
Este usuario es el que hizo la prueba de enviar el correo trampa. Puede ser que el cliente de correo que tiene haga un login primero
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.
Como se desactiva esto? porque la verdad tienes razon lo unico que hace es embrollar 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.
Tienes razon unas pocas lineas mas arriba estaba esto:
Oct 25 16:20:19 adslinux postfix/smtpd[5557]: CDD7331D8E:
client=Luis.iranon.com[192.168.1.132]
Oct 25 16:20:19 adslinux postfix/cleanup[5558]: CDD7331D8E:
message-id=<417D0B0E.1010702@iranon.com>
Oct 25 16:20:19 adslinux postfix/qmgr[32128]: CDD7331D8E:
from=
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.
Curiosamente el proceso 5573 es como la linea de antes: Oct 25 16:20:05 adslinux postfix/smtp[5573]: connect to localhost[::1]: Connection refused (port 10024) Es decir ahi parece que algo deberia haber conectado que no hay y posiblemente de el error
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.
Esto no se decirte igual ha recibido correo con el fetchmail al mismo tiempo.
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
la version que tengo instala ahora mismo es esta: postfix-2.0.19_20040312-11
También puedes aumentar momentaneamente el grado de explicitez del log:
#debug_peer_list = some.domain
Lo hará a ver que sale, a ver si me da alguna pista mas, Saludos y gracias de nuevo por tu tiempo Emi