Probleme mit Spamassassins Bayes Datenbank

[Gelöschtes Mitglied 16444]

Moin,

seit einiger Zeit habe ich Fehlermeldungen von Spamassassin im Log:

spamd[6493]: bayes: expire_old_tokens: child processing timeout at /usr/sbin/spamd line 1319

Zwischen drin auch ab und zu mal

spamd[22985]: bayes: cannot open bayes databases /var/lib/spamassassin/.spamassassin/bayes_* R/W: lock failed: Die Datei existiert bereits

oder

[6438] warn: bayes: expire_old_tokens: __alarm__ignore__(26)

Ich konnte allerdings noch nicht so recht herausfinden, was das Problem ist. Dementsprechend habe ich es auch noch nicht geschafft es zu lösen. Hat jemand von euch einen Hinweis was da schief gehen könnte?

 

[bitmuncher]

Ich vermute, dass dort ein Scan einer Mail zu lange dauert, die dadurch immer wieder in die Queue zurückgeschickt wird. Wie groß ist denn dein Limit für die maximale Email-Größe? Ansich sind das aber auch alles nur Warnungen. Einfach mal das Log-Level runterdrehen. Dann sollten die Meldungen verschwinden.

 

[Chromatin]

Man vermutet auch einen Zusammenhang mit "sa-learn".
Wie oft laesst du das laufen?

Lass mal "sa-learn --force-expire" laufen und gib uns ein Feedback.

PS: "su" zu dem User, unter dem spamd laeuft, sonst erwischt du die falsche Datenbank

 

[Gelöschtes Mitglied 16444]

Hi,

schon mal danke für eure Antworten.

Ich vermute, dass dort ein Scan einer Mail zu lange dauert, die dadurch immer wieder in die Queue zurückgeschickt wird.

# mailq
Mail queue is empty

Wie groß ist denn dein Limit für die maximale Email-Größe?

# postconf | grep size_limitbody_checks_size_limit = 51200
bounce_size_limit = 50000
header_size_limit = 102400
mailbox_size_limit = 0
message_size_limit = 0

Wie oft laesst du das laufen?

Das läuft jede Nacht als cron-job:

/usr/bin/nice /usr/bin/sa-learn --spam /home/username/Maildir/.Spam/{cur,new} >/dev/null 2>&1

Lass mal "sa-learn --force-expire" laufen und gib uns ein Feedback.

Ja, entsprechende Forenbeiträge hatte ich auch schon gefunden. Das läuft recht lange (~3 min), produziert keine Ausgabe und scheint das Problem nicht zu beheben.

Allgemein scheint die Meldung immer dann produziert zu werden, wenn eine Mail rein kommt. Im Log sehe ich jeweils, dass eine Mail reinkommt, an spamassassin gegeben wird, der scannt die (was mit ~1 Minute auch schon recht lange dauert?), dann kommt nach ca. 4 Minuten die Meldung über das timeout und die Nachricht wird endlich zugestellt. Die Mail hängt da also über 5 Minuten rum, bevor sie im Postfach landet.

 

[Chromatin]

Im Log sehe ich jeweils, dass eine Mail reinkommt, an spamassassin gegeben wird, der scannt die (was mit ~1 Minute auch schon recht lange dauert?)

Das deutet auf jeden Fall auf einen timeout hin.

Wenn Du damit leben kannst - lösche deine Datenbanken.
Spam DBs lassen sich ja wieder aufbauen.

 

[Gelöschtes Mitglied 16444]

Der Scan läuft erfolgreich durch. An der Stelle scheint der timeout nicht aufzutreten. Die Mails werden auch alle entsprechend klassifiziert und korrekt einsortiert. Ich hatte schon überlegt, ob die Datenbank vielleicht zu groß geworden ist und der Scan deswegen so lange dauert...

 

[Chromatin]

Ich meinte auch nicht den eigentlichen Scan.
Irgendwas/Irgendein Child wird da herumeiern und dann ueber timeout wegbrechen.

Wie viele Token hast du denn in deiner Datenbank?
Die expire Optionen bei sa-learn und bayes_auto_expire in der config greifen erst ab 100.000 Token.

Hast du die Bayes DB in einer SQL Datenbank oder im FS?

 

[Gelöschtes Mitglied 16444]

Ich meinte auch nicht den eigentlichen Scan.
Irgendwas/Irgendein Child wird da herumeiern und dann ueber timeout wegbrechen.

Ja genau, die Meldung über das Timeout sehe ich ja im Logfile.

Wie viele Token hast du denn in deiner Datenbank?
Die expire Optionen bei sa-learn und bayes_auto_expire in der config greifen erst ab 100.000 Token.

Ich bin mir nicht sicher, wie ich an diese Info komme. aber ein sa-learn --dump spuckt unter anderem diese Zeile aus:

0.000          0     151359          0  non-token data: ntokens

Hast du die Bayes DB in einer SQL Datenbank oder im FS?

Die ist im Dateisystem.

Ich habe jetzt gedacht, vielleicht habe ich auch zu viele unnötige Token in der Datenbank, da ich den Filter ja immer nur mit Spam füttere. Habe deswegen jetzt mal ein sa-learn auf Ham gestartet, das braucht 'ne Weile...

 

[Chromatin]

Um wirklich deine Bayes DB auszuschliessen könntest du mal ein backup machen (sa-learn --backup > /bla/sonstwo.bayes) und deine DB rauswerfen (sa-learn --clean). Und dann mal checken ob Du weiterhin die Fehler/Meldungen bekommst.


Importieren kannste dann wieder mit "--restore"

 

[Gelöschtes Mitglied 16444]

Habe deinen Vorschlag mal ausprobiert. Das Problem besteht auch bei leerer Datenbank weiterhin. Es scheint also nicht am Inhalt zu liegen.

Was mir aufgefallen ist und ich merkwürdig finde ist, dass selbst ein sa-learn --help mehrere Sekunden braucht, bis es eine Ausgabe produziert. Irgendetwas scheint mir da sehr merkwürdig...

 

[bitmuncher]

Reicht dein SA die Mails noch an ein Antivirusprogramm weiter? Wenn ja, reagiert das in einer angemessenen Zeit? Ansonsten würde ich das sa-learn mal mittels strace und ltrace aufrufen um zu schauen bei welchen Funktionsaufrufen das Programm so lange braucht.

 

[Gelöschtes Mitglied 16444]

Nein, ein Antivirenprogramm ist in der Kette nicht mit drin. Wenn eine Mail rein kommt, dann sieht das so aus:

Oct 18 16:29:07 RaspberryPi fetchmail[3334]: 1633 messages (1632 seen) for ******* at pop.gmx.net (245828246 octets).
Oct 18 16:29:07 RaspberryPi postfix/smtpd[5743]: connect from localhost[127.0.0.1]
Oct 18 16:29:07 RaspberryPi postfix/smtpd[5743]: C6EE91E03: client=localhost[127.0.0.1]
Oct 18 16:29:07 RaspberryPi postfix/cleanup[5745]: C6EE91E03: message-id=<20151018142630.b9b0b90d5920@www.hackerboard.de>
Oct 18 16:29:07 RaspberryPi postfix/qmgr[3304]: C6EE91E03: from=<notify@hackerboard.de>, size=4369, nrcpt=1 (queue active)
Oct 18 16:29:07 RaspberryPi fetchmail[3334]: reading message *******@pop.gmx.net:1633 of 1633 (4049 octets) not flushed
Oct 18 16:29:07 RaspberryPi postfix/smtpd[5743]: disconnect from localhost[127.0.0.1]
Oct 18 16:29:08 RaspberryPi spamd[3187]: spamd: connection from localhost [127.0.0.1] at port 59255
Oct 18 16:29:08 RaspberryPi spamd[3187]: spamd: setuid to debian-spamd succeeded
Oct 18 16:29:08 RaspberryPi spamd[3187]: spamd: processing message <20151018142630.b9b0b90d5920@www.hackerboard.de> for debian-spamd:110
Oct 18 16:29:14 RaspberryPi spamd[3187]: spamd: clean message (-1.1/5.0) for debian-spamd:110 in 6.1 seconds, 4288 bytes.
Oct 18 16:29:14 RaspberryPi spamd[3187]: spamd: result: . -1 - BAYES_00,RDNS_NONE scantime=6.1,size=4288,user=debian-spamd,uid=110,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=59255,mid=<20151018142630.b9b0b90d5920@www.hackerboard.de>,bayes=0.000000,autolearn=no
Oct 18 16:34:08 RaspberryPi fetchmail[3334]: 1633 messages (1633 seen) for ******* at pop.gmx.net (245828246 octets).
Oct 18 16:34:11 RaspberryPi spamd[3187]: bayes: expire_old_tokens: child processing timeout at /usr/sbin/spamd line 1319.
Oct 18 16:34:12 RaspberryPi spamd[2804]: prefork: child states: II
Oct 18 16:34:13 RaspberryPi postfix/pipe[5746]: C6EE91E03: to=<******@localhost>, relay=spamassassin, delay=305, delays=0.2/0.17/0/305, dsn=2.0.0, status=sent (delivered via spamassassin service)
Oct 18 16:34:13 RaspberryPi postfix/qmgr[3304]: C6EE91E03: removed
Oct 18 16:34:13 RaspberryPi postfix/pickup[5561]: 26D801E03: uid=110 from=<notify@hackerboard.de>
Oct 18 16:34:13 RaspberryPi postfix/cleanup[5799]: 26D801E03: message-id=<20151018142630.b9b0b90d5920@www.hackerboard.de>
Oct 18 16:34:13 RaspberryPi postfix/qmgr[3304]: 26D801E03: from=<notify@hackerboard.de>, size=4680, nrcpt=1 (queue active)
Oct 18 16:34:13 RaspberryPi dovecot: lmtp(5806): Connect from local
Oct 18 16:34:14 RaspberryPi dovecot: lmtp(5806, ******): nFLfOeWtI1auFgAAy7136Q: sieve: msgid=<20151018142630.b9b0b90d5920@www.hackerboard.de>: stored mail into mailbox 'INBOX'
Oct 18 16:34:14 RaspberryPi postfix/lmtp[5805]: 26D801E03: to=<******@localhost>, relay=**********.de[private/dovecot-lmtp], delay=3, delays=1.8/0.12/0.23/0.79, dsn=2.0.0, status=sent (250 2.0.0 <******@localhost> nFLfOeWtI1auFgAAy7136Q Saved)
Oct 18 16:34:14 RaspberryPi dovecot: lmtp(5806): Disconnect from local: Client quit (in reset)
Oct 18 16:34:14 RaspberryPi postfix/qmgr[3304]: 26D801E03: removed

 

[bitmuncher]

Wie sieht denn der Speicherverbrauch während des Scans aus? Und wie verhält sich spamd, wenn du ihm -L (local tests only) als Parameter mitgibst?

 

[Gelöschtes Mitglied 16444]

Guter Punkt!

Also an den DNS Checks etc. scheint es nicht zu liegen, das macht keinen Unterschied. Top sagt während eines Scans:

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND
22883 debian-s  20   0 41216  36m 4764 R  96,9  7,6   2:25.22 spamd child

Es ist zwar nur ein RaspberryPi, aber das scheint mir dann trotzdem recht hoch. Bestätigt ja eigentlich nur den Verdacht, dass da ein Kindprozess hängen bleibt.