[resolu] Exim: spamcheck transport output

Sur une debian sarge avec un Spamassassin de volatil.

Je viens de perdre quelques mails sur un compte à cause de cette erreur:

[quote]2007-03-03 01:46:50 1HNIJl-0005if-00 monadresse@chezmoi: spamcheck transport output: An error was detected while processing a file of BSMTP input.
2007-03-03 01:46:50 1HNIJl-0005if-00 ** monadresse@chezmoi D=spamcheck_director T=spamcheck: Child process of spamcheck transport returned 2 from command: /usr/sbin/exim[/quote]

Apparemment, c’est spamc qui gère assez mal les ruptures de flux TCP et ça le met dans un état second ainsi qu’exim (cf http://www.exim.org/mail-archives/exim-users/Week-of-Mon-20060206/msg00196.html).
J’ai en fait deux solutions en vue

  1. La première est d’utiliser le spamassassin de Etch. J’ai fait un backport sur
    deb boisson.homeip.net/debian/ sarge divers
    et l’ai installé. A suivre.

  2. La deuxième est de faire la rustine proposé par le gars dans ce message. Ce sera ma solution de repli.

Suis je le seul à avoir eu ce pbm?

[Pour Matt: Sur un autre serveur en woody avec un spamassassin 3.0.2, je n’ai pas ce pbm :imp: , Quelle idée aussi de chercher le neuf et de passer en sarge :slightly_smiling: ]

Eh oh, ça va hein !
Je suis peut être attiré irrationnellement comme tout le monde par le “bleeding edge”, mais je suis le premier à dire que chercher la dernière version sur une machine de prod n’a aucun sens.
Par contre, ce qui me semble important, c’est d’homogeneiser le jeu de paquet avec un upgrade dès qu’on installe du nouveau, pour garder une machine cohérente en terme de versions.
Et sinon, c’est quand même bizarre qu’un tel bug n’ait pas été corrigé en sarge. Tu as remonté des infos dans le BTS ?

J’attends de bien comprendre d’où ça vient, j’ai du mal à bien saisir le fonctionnement des transports d’EXIM et visiblement c’est autour de ça. Par ailleurs comme c’est un paquet volatile, je ne connais pas vraiment le statut de ces paquets. C’est vrai que le bug est sérieux: en gros ça plombe la réception de mails pour un laps de temps non négligeable: 253 mails ont dégagés, ça fait beaucoup :frowning:

Damned, ça a recommencé.

Il semble que le démon spamd se mette dans un état second.
Les messages d’erreurs sont les suivants:

Dans exim(3)

Dans les messages reçus, ça donne

[quote] Child process of spamcheck transport returned 2 from command:
/usr/sbin/exim
An error was detected while processing a file of BSMTP input.
The error message was:

554 Unexpected end of file

The SMTP transaction started in line 0.
The error was detected in line 3.
0 previous messages were successfully processed.
The rest of the batch was abandoned.
554 Unexpected end of file
Transaction started in line 0
Error detected in line 3

------ This is a copy of the message, including all the headers. ------

Return-path: root@mon.domaine
Received: from expourri.rebelles ([192.168.1.247] helo=localhost.localdomain)
by alf94-3-82-66-248-156.fbx.proxad.net with esmtp (Exim 3.35 #1 (Debian))
id 1HPx8M-0004Rb-00
for francois@mon.domaine; Sat, 10 Mar 2007 09:40:58 +0100
Received: from root by localhost.localdomain with local (Exim 4.50)
id 1HPx8S-00017N-HT
for root@localhost.localdomain; Sat, 10 Mar 2007 09:41:04 +0100
From: Anacron root@mon.domaine
To: root@localhost.localdomain
Subject: Anacron job ‘cron.daily’ on expourri
Message-Id: E1HPx8S-00017N-HT@localhost.localdomain
Date: Sat, 10 Mar 2007 09:41:04 +0100
X-Scanner: exiscan 1HPx8M-0004Rb-00.xZ5GWDNhaM*

/etc/cron.daily/lprng:
lp: file ‘hfA338’, age 85.51 hours > 24.00 hours maximum (removing)
lp: file ‘dfA338localhost.localdomain’, age 85.53 hours > 24.00 hours maximum (removing)
[/quote]

Je l’ai mis tel que car je ne comprends pas ce qu’est cette foutue linge 3, c’est la même erreur sur tous les messages refusées. Je soupconne un timeout d’exim qui se déclenche avant le timeout de spamc, mais je n’ai pas réussi à savoir où était ce timeout. J’ai essayé deux choses:

  1. La technique du gars dans le premier message, l’idée n’est pas mauvais qui consiste à dire à spamc de faire seul le chainage. J’ai donc mis
spamcheck:
    driver = pipe
    command = /usr/bin/spamc -p 780 -e /usr/sbin/exim -oMr spam-scanned -bS[/code]

au lieu de
[code]spamcheck:
    driver = pipe
    command = /usr/sbin/exim -oMr spam-scanned -bS
    transport_filter = /usr/bin/spamc -p 780
    bsmtp = all

mais ça me sort une erreur:

[quote] Child process of spamcheck transport returned 2 from command:
/usr/bin/spamc

The following text was generated during the delivery attempt:

------ francois@mon.domaine ------

An error was detected while processing a file of BSMTP input.
The error message was:

500 Command unrecognized

The SMTP transaction started in line 0.
The error was detected in line 1.
The SMTP command at fault was:

X-Spam-Checker-Version: SpamAssassin 3.1.7-deb (2006-10-05) on

0 previous messages were successfully processed.
The rest of the batch was abandoned.
500 Command unrecognized
Transaction started in line 0
Error detected in line 1
X-Spam-Checker-Version: SpamAssassin 3.1.7-deb (2006-10-05) on

------ This is a copy of the message, including all the headers. ------

Return-path: francois@mon.domaine
Received: from totoche.rebelles
([192.168.1.249] helo=totoche ident=francois)
by alf94-3-82-66-248-156.fbx.proxad.net with smtp (Exim 3.35 #1 (Debian))
id 1HQ3Yr-0007BY-00
for francois@mon.domaine; Sat, 10 Mar 2007 16:32:45 +0100
Date: Sat, 10 Mar 2007 16:34:47 +0100
From: Francois Boisson francois@mon.domaine
To: francois@mon.domaine
Subject: test
Message-Id: 20070310163447.5ab97f89.francois@mon.domaine
X-Mailer: Sylpheed version 2.2.3 (GTK+ 2.6.4; i386-pc-linux-gnu)
Mime-Version: 1.0
Content-Type: text/plain; charset=US-ASCII
Content-Transfer-Encoding: 7bit
X-Scanner: exiscan 1HQ3Yr-0007BY-00RKFSfWiW9gQ*

[/quote]

Donc visiblement, ça n’est pas la bonne commande exim, pourtant c’est celle qui est utilisée.

  1. Solution actuelle, j’ai mis un timeout à spamc de 5 minutes en espérant être en dessous de celui d’exim. Mais si ça se trouve je fais fausse route. C’est bizarre car je n’avais pas ce pbm avant avec le serveur sur woody et avec un spamassassin backporté.

Les indices:

Les erreurs sont précédées dans les logs de

[quote]2007-03-10 06:47:34 unexpected EOF while reading SMTP data (header) from mail
2007-03-10 06:47:34 1HPuLd-0003hL-00 <user.anti-spam@m…et>: spamcheck transport output: An error was detected while processing a file of BSMTP input.
[/quote]
L’erreur se déclenche à l’arrivée d’un message et subsiste pendant un temps aléatoire. Je n’ai rien trouvé à ce sujet dans Google de clair…

Ah… Après une lecture attentive de cet incompréhensible manuel d’exim (en Anglais mais ça c’est le coté clair!), il faudrait mettre

spamcheck: driver = pipe command = /usr/bin/spamc -p 780 -e /usr/sbin/exim -oMr spam-scanned -bm -t

et non «-bS», on va essayer comme ça.
[edit: Marche pas lorsque l’adresse du destinataire n’est pas dans les entêtes
du message :frowning: . Retour à la case départ.] :frowning: et même :cry:

Bon, je continue.

Le problème est lié à un fils de spamd qui gèle/boucle/va à la pèche/glande, spamc attends et exim aussi. Le temps d’attente d’exim serait réglable mais ça n’est pas clair. Théoriquement, les réponses de spamd sont obtenues en gros au bout d’une dizaine de secondes. Un délai de 3 minutes à spamc est trop pour exim. Un délai de 1 minutes semble passé. La rustine qui marche serait

[code]spamcheck:
driver = pipe

command = /usr/sbin/exim -oMr spam-scanned -bS
transport_filter = /usr/bin/spamc -t 60 -p 780
bsmtp = all

[/code]Là, les messages sont envoyés même si spamassassin est gelé, simplement ils ne sont pas filtrés. Pour être sur, ja’i mis un délai maximal à spamd:

--timeout-child=59 rajouté dans /etc/default/spamassassin.

Reste à savoir pourquoi cet imbécile de spamassassin gèle.
Vu la présence de [quote]Mar 11 11:52:44 cerbere spamd[16110]: auto-whitelist: open of auto-whitelist file failed: auto-whitelist: cannot open auto_whitelist_path /var/mail/.spamassassin/auto-whitelist: Ioctl() inappropré pour un périphérique
[/quote] dans les logs, je supprime l’auto-whitelist, à suivre…

Matt: Pas d’idées?

Bon le problème semble disparaitre (ou du moins la perte de messages) si on procède comme suit

  1. Reconstruction complète de la base Bayes (je pense que le gel de spamd vient de là)
  2. Mis en place d’un timeout de 60s dans la réponse de spamc et dans la réponse de spamd par une ligne

dans exim.conf

et l’ajout de [quote] --timeout-child=59[/quote]dans les options de spamd (/etc/default/spamassassin.

Dans ces conditions, en cas de souci, spamd devrait renvoyer la main au bout d’une minute, sinon spamc le fait. Dans ce cas, le mail n’est pas traité mais il n’est pas perdu.

  1. Suppression de l’autowhitelist (de toute façon, je n’aime pas ce principe).

Euh je viens de voir que tu y avais reflechi tout seul.
Bravo.
Personnellement, j’aurais sabré exim, mais ta solution est plus élégante :wink:

Bon, cette fois c’est complètement résolu et ça n’est pas exim.

C’est le bug 4950 de spassassin http://issues.apache.org/SpamAssassin/show_bug.cgi?id=4590 que l’on peut résoudre en mettant l’option «–round-robin» dans les options de lancement de spamassassin. C’est en problème dans le fork des spamd fils apparu avec la version sarge de spamassassin, les réglages ci dessus m’ont permis de ne plus perdre de mails, et surtout de trouver un mail qui avait rencontrer le problème et une heure précise ou le pbm a commencé. Les logs ont montré dans mail.info (et là seulement)

[quote]Mar 17 07:55:31 cerbere spamd[8747]: prefork: syswrite(6) to 7687 failed on try 4 at /usr/share/perl5/Mail/SpamAssassin/SpamdForkScaling.pm line 610.
Mar 17 07:55:31 cerbere spamd[8747]: prefork: giving up at /usr/share/perl5/Mail/SpamAssassin/SpamdForkScaling.pm line 612.
Mar 17 07:55:31 cerbere spamd[8747]: prefork: write of ping failed to 7687 fd=6: at /usr/share/perl5/Mail/SpamAssassin/SpamdForkScaling.pm line 343.
Mar 17 07:55:31 cerbere spamd[8747]: prefork: killing failed child 7687 fd=6 at /usr/share/perl5/Mail/SpamAssassin/SpamdForkScaling.pm line 137.
Mar 17 07:55:31 cerbere spamd[8747]: spamd: handled cleanup of child pid 7687 due to SIGCHLD
Mar 17 07:55:31 cerbere spamd[8747]: prefork: killed child 7687
Mar 17 07:55:31 cerbere spamd[8747]: prefork: select returned -1! recovering: Mauvais descripteur de fichier
Mar 17 07:56:02 cerbere last message repeated 31 times
Mar 17 07:56:32 cerbere last message repeated 30 times
[/quote]

Une recherche là dessus plus un épluchage des sources de SpamdForkScaling.pm et une recherche sur fork dans le manuel de spamd m’ont conduit à la solution. Celle ci est confirmé dans http://www.drazzib.com/docs:mail:spamassassin (sans explication)
Ouf!, ça aura mis 15 jours… :slightly_smiling:

Je pensais avoir trouvé la raison du problème, eh ben non. Ce matin,
gel des trois démons spamd (mais aucun message perdu). La version 3.1.7
semble être prémunie contre ce bug 4950). Bon, suite des investigations.
Test sur des messages ayant gelé spamassassin, je constate que ces
messages passent très bien. Cela veut dire que le gel est indépendant
des messages. Peut être que cela vient de la grosseur de la base de
données, cela expliquerait que après chacune de mes interventions tout
se passe bien.

Fort de ces réflexions, je me rappelle de la fonction force-expire de
sal-learn, regardes les options de spamassassin et constate qu’il y a
une fonction auto_expire. Un recherche sur les news avec cette fonction
montre qu’elle entraine un grand délai de spamd avec également une
boucle infernale possible sur le verrouillage de la base bayes. Je
teste donc une nouvelle configuration qui supprime l’auto-expire et je
rajoute dans le crontab, juste après le sa-learn --sync quotidien un
sa-learn --force-expire. Si ma théorie est juste, cela devrait
enfin résoudre mon problème. En conclusion:

  • spamc appelé avec une option -t 60
  • spamd avec l’option --create-prefs --timeout-child=60
    –max-children 3 -c --helper-home-dir
  • Rajout de l’option bayes_auto_expire 0 dans local.cf
    use_bayes 1
    bayes_auto_learn 1
    bayes_auto_expire 0
  • Appel quotidien de sa-learn --force-expire

Ce coup là, ça devrait être bon :slightly_smiling:
[posté sur la DUF aussi]