P3Scan und Mails werden stark verzögert

[theater]

Hallo,

ich setzte den IpCop v2 und den Copfilter für diese Version ein.

Aktiviert sind beim Copfilter der Spamfilter und der Virenscanner für E-Mails. Ich lasse von einem Tobitsoft David Mail Server alle 30 min 102 Pop Boxen abrufen. Seit ca. 10 Tagen werden bei einigen Postfächern die Mails mit ca. 2 Stunden Verzögerung abgeholt. Bevor ich meinem Provider Druck mache würde ich gern ausschließen das am Cop was schief läuft.

Um der Sache auf den Grund zu gehen habe ich sowohl Spamassassin als auch den P3Scan im Debug Modus gestartet. Die Ausgabe der Meldungen erfolg aber nur auf der Konsole. Gibt es eine Möglichkeit die Ausgabe zusätzlich in ein Logfile schreiben zu lassen damit ich mir diese in Ruhe ansehen kann?

Danke schon mal.

[karesmakro]

Hallo theater und willkommen im Copfilter Forum

Seit ca. 10 Tagen werden bei einigen Postfächern die Mails mit ca. 2 Stunden Verzögerung abgeholt.

Gibt es irgendwelche Auffälligkeiten in den p3scan,messages und/oder spamd Logdateien?
Wenn man in den normalen Logs nichts ungewöhnliches feststellen kann, dann wird normal auch der Debug nicht sonderlich ertragreich sein.
Für das Umleiten der Debugausgabe:

Code: Select all

/etc/rc.d/init.d/copfilter_p3scan debug > p3scan-debug.log 2>&1

Code: Select all

/etc/rc.d/init.d/copfilter_spamd debug > spamd-debug.log 2>&1

Das leitet die Ausgabe vollständig um! Die Logdateien werden an dem Ort geschrieben, an dem der Befehl ausgeführt wurde. Wenn du diese gleichzeitig sehen willst, starte eine 2 Sitzung, wechsle in das Verzeichnis, an der die Logdateien geschrieben werden und starte:
tail -f p3scan-debug.log

Wenn für das Spamfiltern alle komponenten aktiviert sind, kann es zu größeren Verzögerungen kommen. Das beträgt im Moment für die Mail ~25-30 Sekunden und es werden je nach Anzahl der Spamassassin Prozesse x Mails gleichzeitig gescannt.

Welche Copfilter Version verwendet ihr?

Grüße

[theater]

Hallo und danke für die Begrüßung und ausführliche Anleitung.

Wir verwenden die Copfilter Version 2.0.90

Beim Spamfilter ist nur Spamassassin und die Razor, DCC, DNSBL Listen aktiviert. Außerdem werden die Mails mit ClaimAV gescheckt. Für P3Scan laufen 2 Prozesse und für Spamassassin 3.

Laut Log dauert der Scan wie du schon geschrieben hast zwieschen 20 - 30 Sek. Ich kann in den Logs für P3Scan und Spamassassin keinerlei errors, timeouts oder andere ungewöhnliche Sachen entdecken. Die messages.log habe ich noch nicht tiefer durchforstet weil da ja alles "kreuz und quer" drin steht. Da brauche ich erstmal ruhe mich da durchzuarbeiten.

Irgendwie habe ich den Eindruck das der Server beim Provider die Mails nicht raus rückt oder beim pollen nicht meldet das neue Mails da sind. Hatte auch schon den Fall das ich in der Webbox beim Provider nen Mails gesehnen habe die erst Stunden später hier bei uns im Posteingang gelandet ist.

Habe gerade doch was entdeckt:

Code: Select all

warn: util: failed to spawn a process "/var/log/copfilter/default/opt/dcc/bin/dccproc, -H, -x, 0, -a, 81.3.18.58": error closing STDERR: Inappropriate ioctl for device at /var/log/copfilter/default/opt/mail-spamassassin/3.3.2/lib/Mail/SpamAssassin/Util.pm line 1519. at /var/log/copfilter/default/opt/mail-spamassassin/3.3.2/lib/Mail/SpamAssassin/Util.pm line 1440.

Thu Jan 26 16:03:36 2012 [23812] dbg: util: force_die: util: failed to spawn a process "/var/log/copfilter/default/opt/dcc/bin/dccproc, -H, -x, 0, -a, 81.3.18.58": error closing STDERR: Inappropriate ioctl for device at /var/log/copfilter/default/opt/mail-spamassassin/3.3.2/lib/Mail/SpamAssassin/Util.pm line 1519.

Thu Jan 26 16:03:36 2012 [28432] info: dcc: [23812] finished: exit 6

Thu Jan 26 16:03:36 2012 [28432] dbg: dns: leaving helper-app run mode

Thu Jan 26 16:03:36 2012 [28432] warn: dcc: check failed: failed to read header

finde ich sporadisch im Spamassassin Log. Gleube aber nicht das das was mit dem Problem zu tun hat.

[karesmakro]

Hallo

Laut Log dauert der Scan wie du schon geschrieben hast zwieschen 20 - 30 Sek.

Und das finde ich mittlerweile zu lange! Ich werde mir das die nächsten Tage nochmal genauer ansehen!

Die messages.log habe ich noch nicht tiefer durchforstet weil da ja alles "kreuz und quer" drin steht.

Code: Select all

cat /var/log/messages | grep 'terminated\|ERR\|error' | grep p3scan

btw.

Code: Select all

zcat /var/log/messages-2012 | grep 'terminated\|ERR\|error' | grep p3scan

und das gleiche mit spamd

Code: Select all

cat /var/log/messages | grep 'terminated\|failed\|error' | grep spamd

Eine entscheidende Frage ist noch deine Hardware Ausstattung des Cops!?
Zudem wäre noch die Auslastung mit top interessant, wenn dein Mailserver diese 102 Mailboxen abruft!

Ich lasse von einem Tobitsoft David Mail Server alle 30 min 102 Pop Boxen abrufen.

Gibt es da Logdateien/Auffälligkeiten?

Grüße

[karesmakro]

Ich empfehle für schwächer gerüstete PC's dringend den Detailierungsgrad in den Protokolleinstellungen von IPCop auf niedrig zu stellen!

Hintergrund:
Die IPCop Skripte für die Analyse verbrauchen um so mehr Systemressourcen, je höher der Detailierungsgrad eingestellt ist und benötigen je nach CPU und RAM bis zu mehrere Minuten. Fällt ein Mailabruf genau auf diesen Zeitraum, steigen die Scanzeiten von Spamassassin ganz beträchtlich. Ich gehe mal davon aus, daß die meisten Clients wie Outlook, Exchange, Thunderbird, fetchmail, usw. per Scheduler alle 5 / 15 / 30 usw. Minuten die Mails abrufen, was natürlich die Wahrscheinlichkeit erhöht, in diesen Zeitrahmen zu fallen....

Falls Probleme mit p3scan/proxsmtp und spamassassin auftreten, müssen zudem die Timeout Einstellungen der einzelnen Komponenten berücksichtigt werden. Dazu gehören p3scan (per default 120 Sekunden), proxsmtp (per default 180 Sekunden) und auch der Client, der die Mails abruft.
Unter Umständen kann der Scan dann mehr als 90 Sekunden betragen!
Mit top überprüfen, wie hoch die Systemlast des Cops während der Scans ist.

@FischerM: ich denke, wir sollten dieses Thema unter Troubleshootings im Wiki mit aufnehmen

Ich habe für die Copfilter Versionen 2.0.90 und 2.0.91beta1 einen Patch vorbereitet, der die Antispam GUI um eine Funktion erweitert. Man kann die RBL Checks deaktivieren, wenn Razor, DNSBL und DCC aktiviert ist. Dadurch sollten die Scanzeiten nochmals sinken! (Wäre um ein Feedback dankbar)

Für Copfilter 2.0.90
http://www.copfilter.org/v2-downloads/g ... peedup.tgz
md5sum: a5ca5bbabc2e69ba0286778eea3a0dbe

Für Copfilter 2.0.91beta1
http://www.copfilter.org/v2-downloads/g ... peedup.tgz
md5sum: f0d3e48ef0e1b2137626c699602eb4e8

[FischerM]

@FischerM: ich denke, wir sollten dieses Thema unter Troubleshootings im Wiki mit aufnehmen

Done:

http://www.copfilter.org/wiki/doku.php? ... zoegert_v2 (deutsch)
http://www.copfilter.org/wiki/doku.php? ... delayed_v2 (englisch)

Gruß
Matthias

[theater]

Hallo,

sorry hatte die Woche viel um die Ohren und komme jetzt erst dazu mich wieder mit dem Copfilter zu befassen.

Hier mal die Daten zu dem Rechner:

P4 mit 1.7 GHz
2 GB Ram
IDE Platte mit 40 GB

Root Partition 755 MB davon 643 belegt
Log Partition 38 GB davon 4.6 GB belegt


Die Auslastung mit top zeigt bei spamd im Mittel 25 - 30 % an. Geht aber schon mal bis 80 - 85 % rauf.

Was mir aber aufgefallen ist. Wenn der Prozess makegraph dazu kommt steigt die CPU Auslastung auf 100 %.


Auf dem David Server gibt es keine Errors oder Timeouts. Wobei jeder der das Ding kennt über die Logfiles zumindest bis zur Version 10 fluchen wird.

Werde den Patch probieren und Feedback geben. Natürlich werde ich auch den Detailierungsgrad anpassen.

Danke.


Habe gerade den Patch probiert. Leider läßt der sich nicht installieren bzw. meldet das er schon installiert sei. Somit sehe ich auch die neu Einstellung nicht zum deaktivieren der RBL nicht.

Code: Select all

Copfilter v2 spamassassin speedup ...

check ....Speedup already installed! Exiting ....

Habe den aber definitiv noch nicht installiert.

[karesmakro]

Hallo,

ich denke, daß es eher etwas mit dem makegraph zu tun hat. Soweit ich mitbekommen habe, wird der Detailierungsgrad "Hoch" in der kommenden IPCop 2.0.3 deaktiviert sein!

Ich würde auf der Root-Partition wieder etwas platz schaffen! Wieviel Swap hast du dem System zugewiesen?

Wg. dem RBL-Check, lade dir die Version bitte nochmal herunter! Ich hatte übersehen, daß ein Ausrufezeichen fehlt.

Für Copfilter 2.0.90
http://www.copfilter.org/v2-downloads/g ... peedup.tgz
md5sum: a5ca5bbabc2e69ba0286778eea3a0dbe

Für Copfilter 2.0.91beta1
http://www.copfilter.org/v2-downloads/g ... peedup.tgz
md5sum: f0d3e48ef0e1b2137626c699602eb4e8

[theater]

Hallo,

leider kommt bei der Installation folgenden Meldung. Das Auswahlfeld unter Antispam erscheint aber.

Code: Select all

Copfilter v2 spamassassin speedup ...

check ....
Patching copfilter_antispam.cgi ...patching file /home/httpd/cgi-bin/copfilter_antispam.cgi

Patching copfilter_spamd ...patching file /var/log/copfilter/default/opt/mail-spamassassin/etc/init.d/copfilter_spamd
patch: **** malformed patch at line 23: 's/.*use_dcc.*/use_dcc 0/' > /tmp/local.cf.tmp.$$


exiting ...

Habe etwas aufgeräumt. Auf der Root Partition sind jetzt ca. 276 MB frei.

Das Swapfile ist 256 MB groß. Das wird aber kaum genutzt. Laut Systemdiagramm gerade mal so 2 MB.

Muß auch die Angabe zum Arbeitsspeicher korrigieren es sind nur 1 GB. Habe ich im Eifer des Gefechts gestern falsch angegeben. Sorry.

Danke für deine Mühe.


Hier noch die Ausgaben der messages von zcat für spamd:

Code: Select all

Jan 12 20:30:26 tfn-bipcop spamd[24340]: dcc: [31734] terminated: exit 241
Jan 13 10:01:07 tfn-bipcop spamd[24340]: dcc: [24807] terminated: exit 241
Jan 14 14:00:27 tfn-bipcop spamd[14917]: dcc: [25475] terminated: exit 241
Jan 14 18:45:32 tfn-bipcop spamd[14917]: dcc: [2308] terminated: exit 241
Jan 14 21:45:42 tfn-bipcop spamd[14917]: dcc: [6154] terminated: exit 241
Jan 15 16:45:44 tfn-bipcop spamd[14917]: dcc: [2600] terminated: exit 241
Jan 17 14:00:35 tfn-bipcop spamd[20938]: dcc: [23270] terminated: exit 241
Jan 17 20:15:32 tfn-bipcop spamd[20938]: dcc: [14091] terminated: exit 241
Jan 19 12:52:36 tfn-bipcop spamd[25394]: dcc: [4172] terminated: exit 241
Jan 19 14:54:16 tfn-bipcop spamd[25394]: dcc: [11296] terminated: exit 241
Jan 19 19:18:19 tfn-bipcop spamd[25394]: dcc: [24556] terminated: exit 241
Jan 20 11:36:03 tfn-bipcop spamd[2269]: dcc: [20319] terminated: exit 241
Jan 20 20:22:27 tfn-bipcop spamd[2269]: dcc: [9457] terminated: exit 241
Jan 22 21:15:31 tfn-bipcop spamd[1082]: dcc: [9040] terminated: exit 241

... und für p3scan:

Code: Select all

Jan 23 09:35:38 tfn-bipcop p3scan[24649]: ERR: Cannot connect to real-server: 83.246.103.136
Jan 23 15:38:40 tfn-bipcop p3scan[16600]: ERR: We cot SIGTERM!
Jan 23 15:38:40 tfn-bipcop p3scan[16581]: ERR: We cot SIGTERM!
Jan 23 20:11:12 tfn-bipcop p3scan[32617]: ERR: Client disappeared during mail send!
Jan 23 20:11:12 tfn-bipcop p3scan[32617]: ERR: Can't send to server!
Jan 24 01:42:27 tfn-bipcop p3scan[11134]: ERR: Cannot connect to real-server: 212.227.17.171
Jan 25 13:16:32 tfn-bipcop p3scan[28450]: ERR: PID file /var/log/copfilter/default/opt/p3scan/var/run/p3scan.pid exists! Aborting!
Jan 25 13:16:32 tfn-bipcop p3scan[28450]: ERR: Exiting now...#012
Jan 27 03:00:09 tfn-bipcop p3scan[22121]: ERR: Cannot connect to real-server: 83.246.103.136
Jan 27 23:12:25 tfn-bipcop p3scan[6506]: ERR: Cannot connect to real-server: 83.246.103.136
Jan 28 03:00:09 tfn-bipcop p3scan[10741]: ERR: Cannot connect to real-server: 83.246.103.136
Jan 29 03:00:09 tfn-bipcop p3scan[4505]: ERR: Cannot connect to real-server: 83.246.103.136
Jan 31 03:00:13 tfn-bipcop p3scan[2859]: ERR: Cannot connect to real-server: 83.246.103.136

Wobei gegen 3:00 Uhr Nachts die Zwangstrennung erfolgt.

Im Moment hat sich die Scanzeit von Spamd bei unter 20 sek eingepegelt. Es gibt aber noch Ausreißer mit um die 38 bis 48 sek.

[mEz]

Hallo zusammen,

habe zwar nicht das selbe Problem aber ein ähnliches und schliesse mich hier jetzt einfach mal an.

Kurz ein paar Details zum IPCOP-System:
CPU: AMD Athlon XP 2400+
RAM: 1024 MB
HDD: 80GB
Seit kurzen nutzen wir IPCOP v. 2.0.2 mit COPFILTER v. 2.0.90 + COPFILTER v. 2.0.90 IPCOP 2.0.x Update.
Es laufen alle Dienste vom Copfilter bis auf FROX.
Alles läuft soweit ganz gut bis auf den Abruf von einer Mailbox. Bei eingeschaltetem SPAMD, CLAMD und P3SCAN bekomme ich eine Fehlermeldung von unserem Email-Server es unmöglich sei den Maildrop zu schliessen. Komisch ist das alle anderen erreichbar sind. Schalte ich die genannten Dienste aus läuft wieder alles Problemlos.
Unser interner Email-Server ist wie im Beitrag schon erwähnt auch ein Tobit.David.

Fehlermeldung von David:

Code: Select all

Server Reply -ERR [IN-USE] Unable to lock maildrop: Mailbox is locked by POP server 

Auf dem IPCOP in den Logs konnte ich folgendes ausfindig machen:

Code: Select all

Feb  9 17:02:04 ipcopf p3scan[16726]: ERR: Writing to client!
Feb  9 17:02:04 ipcopf p3scan[16726]: Session done (Critical abort). Mails: 1 Bytes: 0
Feb  9 17:02:04 ipcopf p3scan[14348]: ERR: File Error! Could not erase /var/log/copfilter/default/opt/p3scan/tmp/children/16726/p3scan.JkC5Bb.dir

und dieses

Code: Select all

Feb  9 17:06:35 ipcopf p3scan[17092]: ERR: We cot SIGTERM!
Feb  9 17:06:35 ipcopf p3scan[17088]: ERR: We cot SIGTERM!
Feb  9 17:06:35 ipcopf p3scan[14348]: signalled, doing cleanup
Feb  9 17:06:35 ipcopf p3scan[14348]: P3Scan terminates now

Ich hoffe jemand kann mir helfen und mir im besten Fall eine Lösung nennen.
Vielen Dank schon einmal im Voraus!

Beste Grüße mEz