On 02/19/14 23:29, Andrei Brezan wrote:
Hello list,
Recently I'm having issues with delays due to
amavisd-new/spamassassin. With log level increased to 5 in
amavisd.conf I get this out of the logs:
Feb 19 22:55:17 hostname amavis[1215]: (01215-01) p001 1 Content-Type:
text/plain, size: 7 B, name:
*snip*
Feb 19 23:00:17 tilaa1 amavis[1215]: (01215-01) _WARN: bayes:
expire_old_tokens: __alarm__ignore__(79)
Feb 19 23:00:17 tilaa1 amavis[1215]: (01215-01) SA info: check:
exceeded time limit in
Mail::SpamAssassin::Plugin::Check::_eval_tests_type11_prineg400_set3,
skipping further tests
Feb 19 23:00:17 tilaa1 amavis[1215]: (01215-01) _WARN: Use of
uninitialized value in concatenation (.) or string at
/usr/local/lib/perl5/site_perl/5.16/Mail/SpamAssassin/PerMsgStatus.pm
line 1258.
Feb 19 23:00:17 tilaa1 amavis[1215]: (01215-01) _WARN: Use of
uninitialized value in numeric eq (==) at
/usr/local/lib/perl5/site_perl/5.16/Mail/SpamAssassin/PerMsgStatus.pm
line 424.
*snip*
Feb 19 23:00:18 tilaa1 amavis[1215]: (01215-01) TIMING-SA total 300188
ms - parse: 3 (0.0%), extract_message_metadata: 18 (0.0%),
poll_dns_idle: 2 (0.0%), get_uri_detail_list: 0.60 (0.0%),
tests_pri_-1000: 17 (0.0%), tests_pri_
-950: 1.89 (0.0%), tests_pri_-900: 1.91 (0.0%), tests_pri_-400: 300094
(100.0%), check_bayes: 300088 (100.0%), expire_bayes: 298067 (99.3%),
get_report: 0.81 (0.0%)
Feb 19 23:00:18 tilaa1 amavis[1215]: (01215-01) size: 1980, TIMING
[total 301147 ms] - SMTP greeting: 7 (0%)0, SMTP EHLO: 3 (0%)0, SMTP
pre-MAIL: 1 (0%)0, mkdir tempdir: 2 (0%)0, create email.txt: 1 (0%)0,
SMTP pre-DATA-flush:
6 (0%)0, SMTP DATA: 100 (0%)0, check_init: 1 (0%)0, digest_hdr: 6
(0%)0, digest_body_dkim: 35 (0%)0, mkdir parts: 5 (0%)0, mime_decode:
9 (0%)0, get-file-type1: 174 (0%)0, parts_decode: 0 (0%)0,
check_header: 1 (0%)0, AV-scan-1
: 32 (0%)0, spam-wb-list: 4 (0%)0, SA msg read: 1 (0%)0, SA parse: 6
(0%)0, SA check: 300179 (100%)100, decide_mail_destiny: 9 (0%)100,
notif-quar: 1 (0%)100, fwd-connect: 33 (0%)100, fwd-mail-pip: 325
(0%)100, fwd-rcpt-pip: 0
(0%)100, fwd-data-chkpnt: 0 (0%)100, write-header: 1 (0%)100,
fwd-data-contents: 0 (0%)100, fwd-end-chkpnt: 178 (0%)100,
prepare-dsn: 2 (0%)100, main_log_entry: 15 (0%)100, update_snmp: 5
(0%)100, SMTP pre-response: 1 (0%)100,
SMTP response: 2 (0%)100, unlink-2-files: 1 (0%)100, rundown: 1 (0%)100
Feb 19 23:00:18 tilaa1 amavis[1215]: (01215-01) extra modules loaded:
unicore/lib/Gc/Nd.pl
Can anyone shed some light into what _eval_tests_type11_prineg400_set3
means and where does it come from?
Not all e-mails get the same treatment, some that reach same 01215-01
process get through without delays and then even a plain text e-mail
induces this delay.
I'm running this postfix/amavisd-new under FreeBSD 9.1-RELEASE.
Thank you,
Andrei
For the record, the issue seems it was the bayes database which I didn't
tend to previously, at least from my understanding. This fixed the
timeout issue:
% sudo su - vscan
Password:
$ sa-learn --force-expire --rebuild
The --rebuild option has been deprecated. Please use --sync instead.
bayes: synced databases from journal in 0 seconds: 258 unique entries (259
total entries)
load: 1.54 cmd: perl 29288 [runnable] 147.32r 62.20u 0.08s 100% 35872k
load: 1.67 cmd: perl 29288 [runnable] 165.25r 75.96u 0.08s 100% 35872k
load: 1.37 cmd: perl 29288 [runnable] 225.48r 120.76u 0.11s 100% 35872k
load: 1.61 cmd: perl 29288 [runnable] 309.96r 176.72u 0.21s 78% 36100k
load: 1.34 cmd: perl 29288 [runnable] 388.33r 224.64u 0.32s 93% 36100k
load: 1.24 cmd: perl 29288 [runnable] 405.48r 236.96u 0.35s 96% 36100k
expired old bayes database entries in 423 seconds
161948 entries kept, 2257326 deleted
token frequency: 1-occurrence tokens: 61.18%
token frequency: less than 8 occurrences: 12.56%
Regards,
Andrei
