MySQL Bayes and timeout in amavisd

Fri Sep 27 10:50:55 CEST 2013

Hello list,

I like to re-ask my question from march this year, as it is still an issue:

I run a setup with postfix 2.5.13 and amavisd-new 2.7.2 in pre-queue 
configuration. Spamassassin (3.3.2) uses a MySQL DB as bayes storage backend.
When the MySQL DB is under high load amavisd takes too long to process a 
message which causes postfix to reject messages and report "queue file write 
errors". Below is the log of such a message as an example.
I'm wondering why amavisd takes more than 2 hours to process that message and 
doesn't quit after 120 seconds despite $child_timeout = 120?
Is it possible to configure amavisd/spamassassin in such a way that it will 
quit if it can not receive an result from the bayes DB in less than X seconds?

/etc/amavisd.conf:
....
$child_timeout = 120;
....

/etc/postfix/main.cf:
....
smtpd_proxy_timeout = 125
....

/etc/mail/spamassassin/local.cf
....
use_bayes 1
bayes_store_module Mail::SpamAssassin::BayesStore::MySQL
bayes_sql_dsn DBI:mysql:spamassassin:db.example.com;mysql_client_found_rows=0
....

/var/log/mail.log:
....
Mar 25 11:51:43 server postfix/smtpd[5706]: setting up TLS connection from 
host.example.com[AA.BB.CC.DD]
Mar 25 11:51:43 server postfix/smtpd[5706]: Anonymous TLS connection 
established from host.example.com[AA.BB.CC.DD]: TLSv1 with cipher DHE-RSA-
AES256-SHA (256/256 bits)
Mar 25 11:51:43 server postfix/smtpd[5706]: NOQUEUE: 
client=host.example.com[AA.BB.CC.DD]
Mar 25 11:51:43 server amavis[3513]: (03513-10) ESMTP:[::1]:10024 
/var/spool/amavis/tmp/amavis-20130325T113759-03513-W3bG5EF4: 
<user at example.com> -> <myuser at mydomain.tld> SIZE=11623 Received: from 
server.mydomain.tld ([IPv6:::1]) by localhost (server.rus.uni-stuttgart.de 
[IPv6:::1]) (amavisd-new, port 10024) with ESMTP for <myuser at mydomain.tld>; 
Mon, 25 Mar 2013 11:51:43 +0100 (CET)
Mar 25 11:51:43 server amavis[3513]: (03513-10) Checking: NWnem1z1wdjP 
[AA.BB.CC.DD] <user at example.com> -> <myuser at mydomain.tld>
Mar 25 11:53:48 server postfix/smtpd[5706]: warning: timeout talking to proxy 
localhost:10024

Mar 25 12:01:10 server postfix/smtpd[5706]: timeout after END-OF-MESSAGE from 
host.example.com[AA.BB.CC.DD]
Mar 25 12:01:10 server postfix/smtpd[5706]: disconnect from 
host.example.com[AA.BB.CC.DD]
Mar 25 13:52:06 server amavis[3513]: (03513-10) _WARN: rules: failed to run 
BAYES_99 test, skipping:\n\t(__alarm__ignore__(640)\n)
Mar 25 13:52:06 server amavis[3513]: (03513-10) SA info: check: exceeded time 
limit in Mail::SpamAssassin::Plugin::Check::_eval_tests_type11_prineg400_set3, 
skipping further tests
Mar 25 13:52:06 server amavis[3513]: (03513-10) _WARN: Use of uninitialized 
value in concatenation (.) or string at 
/usr/lib/perl5/vendor_perl/5.10.0/Mail/SpamAssassin/PerMsgStatus.pm line 1256, 
<GEN36> line 632.
Mar 25 13:52:06 server amavis[3513]: (03513-10) _WARN: Use of uninitialized 
value in numeric eq (==) at 
/usr/lib/perl5/vendor_perl/5.10.0/Mail/SpamAssassin/PerMsgStatus.pm line 424, 
<GEN36> line 632.
Mar 25 13:52:06 server amavis[3513]: (03513-10) spam-tag, <user at example.com> -
> <myuser at mydomain.tld>, No, score=0.001 tagged_above=-999 required=5 
tests=[TIME_LIMIT_EXCEEDED=] autolearn=unavailable
Mar 25 13:52:06 server amavis[3513]: (03513-10) FWD from <user at example.com> -> 
<myuser at mydomain.tld>,BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 
250 2.0.0 Ok: queued as 32A69DB9D2
Mar 25 13:52:06 server amavis[3513]: (03513-10) Passed CLEAN {RelayedInbound}, 
[AA.BB.CC.DD]:7256 [AA.BB.CC.DD] <user at example.com> -> <myuser at mydomain.tld>, 
Message-ID: <DD0CED2EE6F0084AB79B3A6E1C896BD7032CEF5F at DAGNODE8.example.com>, 
mail_id: NWnem1z1wdjP, Hits: 0.001, size: 12214, queued_as: 32A69DB9D2, 
7222602 ms
Mar 25 13:52:06 server amavis[3513]: (03513-10) TIMING-SA total 7222478 ms - 
parse: 2 (0.0%), extract_message_metadata: 31 (0.0%), get_uri_detail_list: 4 
(0.0%), tests_pri_-1000: 8 (0.0%), tests_pri_-950: 0.85 (0.0%), 
tests_pri_-900: 0.93 (0.0%), tests_pri_-400: 7222406 (100.0%), check_bayes: 
7222395 (100.0%), poll_dns_idle: 4 (0.0%), get_report: 1.23 (0.0%)
Mar 25 13:52:06 server amavis[3702]: (03702-08) size: 2533, TIMING [total 
7224796 ms] - SMTP greeting: 1 (0%)0, SMTP EHLO: 0 (0%)0, SMTP pre-MAIL: 0 
(0%)0, SMTP pre-DATA-flush: 2 (0%)0, SMTP DATA: 9 (0%)0, check_init: 1 (0%)0, 
digest_hdr: 1 (0%)0, digest_body: 0 (0%)0, custom-new: 1 (0%)0, check_header: 
2 (0%)0, AV-scan-1: 4 (0%)0, AV-scan-2: 22 (0%)0, spam-wb-list: 0 (0%)0, SA 
parse: 2 (0%)0, SA check: 7224668 (100%)100, custom-checks: 8 (0%)100, 
decide_mail_destiny: 1 (0%)100, notif-quar: 0 (0%)100, custom-before_send: 0 
(0%)100, fwd-connect: 4 (0%)100, fwd-xforward: 0 (0%)100, fwd-mail-pip: 1 
(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: 57 (0%)100, custom-
after_send: 0 (0%)100, prepare-dsn: 0 (0%)100, main_log_entry: 6 (0%)100, 
update_snmp: 2 (0%)100, custom-mail_done: 0 (0%)100, SMTP pre-response: 0 
(0%)100, SMTP response: 0 (0%)100, unlink-1-files: 0 (0%)100, rundown: 0 
(0%)100
Mar 25 13:52:06 server amavis[3513]: (03513-10) size: 12214, TIMING [total 
7222606 ms] - SMTP greeting: 1 (0%)0, SMTP EHLO: 0 (0%)0, SMTP pre-MAIL: 0 
(0%)0, SMTP pre-DATA-flush: 2 (0%)0, SMTP DATA: 13 (0%)0, check_init: 1 (0%)0, 
digest_hdr: 1 (0%)0, digest_body: 0 (0%)0, custom-new: 1 (0%)0, check_header: 
2 (0%)0, AV-scan-1: 9 (0%)0, AV-scan-2: 23 (0%)0, spam-wb-list: 0 (0%)0, SA 
parse: 3 (0%)0, SA check: 7222469 (100%)100, custom-checks: 8 (0%)100, 
decide_mail_destiny: 1 (0%)100, notif-quar: 0 (0%)100, custom-before_send: 0 
(0%)100, fwd-connect: 4 (0%)100, fwd-xforward: 0 (0%)100, fwd-mail-pip: 1 
(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: 55 (0%)100, custom-
after_send: 0 (0%)100, prepare-dsn: 0 (0%)100, main_log_entry: 7 (0%)100, 
update_snmp: 2 (0%)100, custom-mail_done: 0 (0%)100, SMTP pre-response: 0 
(0%)100, SMTP response: 0 (0%)100, unlink-1-files: 0 (0%)100, rundown: 0 
(0%)100
Mar 25 13:52:06 server amavis[3513]: (03513-10) Requesting process rundown 
after 10 tasks (and 10 sessions)
....

Thanks
Stefan