Hi,
I am having problems with amavis causing delays when sending e-mails.
The following is a log snippet:
Mar 27 05:55:40 mail amavis[4726]: (04726-02) ESMTP :10024
/var/lib/amavis/tmp/amavis-20190327T050446-04726-_QtjuYzP:
<a.u...@domain.com> -> <supp...@clearcenter.com> SIZE=495057
Received: from mail.domain.com ([127.0.0.1]) by localhost
(mail.domain.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP
for <supp...@clearcenter.com>; Wed, 27 Mar 2019 05:55:40 -0600 (CST)
Mar 27 05:55:40 mail amavis[4726]: (04726-02) Checking: G7i34mNU8cq2
[127.0.0.1] <a.u...@domain.com> -> <some...@anotherdomain.com>
Mar 27 05:55:40 mail amavis[4726]: (04726-02) p003 1 Content-Type:
multipart/alternative
Mar 27 05:55:40 mail amavis[4726]: (04726-02) p001 1/1 Content-Type:
text/plain, size: 186203 B, name:
Mar 27 05:55:40 mail amavis[4726]: (04726-02) p002 1/2 Content-Type:
text/html, size: 277848 B, name:
Mar 27 06:00:46 mail amavis[4726]: (04726-02) _WARN: bayes:
expire_old_tokens:
__alarm__ignore__(124/::Plugin::Check::run_eval_tests/1105)
Mar 27 06:00:46 mail amavis[4726]: (04726-02) SA info: check:
exceeded time limit in
Mail::SpamAssassin::Plugin::Check::_eval_tests_type11_prineg90_set3,
skipping further tests
Mar 27 06:00:46 mail amavis[4726]: (04726-02) dkim: candidate
originators: From:<a.u...@domain.com>
Mar 27 06:00:46 mail amavis[4726]: (04726-02) dkim: not signing,
empty signing domain, From: <a.u...@domain.com>
Mar 27 06:00:46 mail amavis[4726]: (04726-02) G7i34mNU8cq2 FWD from
<a.u...@domain.com> -> <some...@anotherdomain.com>, BODY=7BIT 250
2.0.0 from MTA(smtp:[127.0.0.1]:10026): 250 2.0.0 Ok: queued as
609033810340A
Mar 27 06:00:46 mail amavis[4726]: (04726-02) Passed CLEAN
{RelayedOutbound}, LOCAL [127.0.0.1]:51006 [216.184.125.213]
<a.u...@domain.com> -> <some...@anotherdomain.com>, Queue-ID:
8A45D3810854C, Message-ID:
<!&!AAAAAAAAAAAYAAAAAAAAAEIkvn8d4wRHi+Y6nVMEnDvCgAAAEAAAAE5dsEsxWUBKnr4M+HVpVToBAAAAAA==@domain.com>,
mail_id: G7i34mNU8cq2, Hits: -2.898, size: 495057, queued_as:
609033810340A, 305783 ms
Mar 27 06:00:46 mail amavis[4726]: (04726-02) TIMING-SA total 300830
ms - parse: 36 (0.0%), extract_message_metadata: 1110 (0.4%),
get_uri_detail_list: 451 (0.2%), tests_pri_-1000: 432 (0.1%),
tests_pri_-950: 6 (0.0%), tests_pri_-900: 29 (0.0%), tests_pri_-90:
299180 (99.5%), check_bayes: 299167 (99.4%), b_tokenize: 1423
(0.5%), b_tok_get_all: 149 (0.0%), b_comp_prob: 79 (0.0%),
b_tok_touch_all: 0.86 (0.0%), b_finish: 297503 (98.9%),
expire_bayes: 297448 (98.9%), get_report: 1.86 (0.0%)
Mar 27 06:00:46 mail amavis[4726]: (04726-02) size: 495057, TIMING
[total 305790 ms] - SMTP greeting: 2.5 (0%)0, SMTP EHLO: 0.9 (0%)0,
SMTP pre-MAIL: 0.9 (0%)0, SMTP pre-DATA-flush: 4.7 (0%)0, SMTP DATA:
79 (0%)0, check_init: 0.7 (0%)0, digest_hdr: 2.2 (0%)0,
digest_body_dkim: 6 (0%)0, collect_info: 3.5 (0%)0, mime_decode: 129
(0%)0, get-file-type2: 150 (0%)0, parts_decode: 0.4 (0%)0,
check_header: 0.9 (0%)0, AV-scan-1: 4409 (1%)2, spam-wb-list: 0.7
(0%)2, SA parse: 38 (0%)2, SA check: 300790 (98%)100,
decide_mail_destiny: 23 (0%)100, notif-quar: 0.7 (0%)100,
fwd-connect: 35 (0%)100, fwd-mail-pip: 46 (0%)100, fwd-rcpt-pip: 0.4
(0%)100, fwd-data-chkpnt: 0.1 (0%)100, write-header: 1.2 (0%)100,
fwd-data-contents: 21 (0%)100, fwd-end-chkpnt: 28 (0%)100,
prepare-dsn: 1.1 (0%)100, report: 2.2 (0%)100, main_log_entry: 7
(0%)100, update_snmp: 3.1 (0%)100, SMTP pre-response: 0.5 (0%)100,
SMTP response: 0.3 (0%)100, unlink-3-files: 1.1 (0%)100, rundown:
1.2 (0%)100
I am not sure how to read this but the TIMING and TIMING-SA figures are
huge with tests_pri_-90: 299180, b_finish: 297503 and expire_bayes:
297448 jumping out to me. I am not aware of using bayes filtering.
Is anyone able to give me any pointers (even if it is just to go to the
spamassassin lists). Is 300,000ms (5 mins) normal? It only seems to be
on outbound e-mails.
Thanks,
Nick
