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: <u...@example.com> -> <myu...@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 <myu...@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] <u...@example.com> -> <myu...@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, <u...@example.com> - > <myu...@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 <u...@example.com> -> <myu...@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] <u...@example.com> -> <myu...@mydomain.tld>, Message-ID: <dd0ced2ee6f0084ab79b3a6e1c896bd7032ce...@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