Delays when scanning outbound e-mails
Nick Howitt
nick at howitts.co.uk
Wed Mar 27 15:39:31 CET 2019
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.user at domain.com> -> <support at 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 <support at 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.user at domain.com> -> <someone at 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.user at domain.com>
Mar 27 06:00:46 mail amavis[4726]: (04726-02) dkim: not signing,
empty signing domain, From: <a.user at domain.com>
Mar 27 06:00:46 mail amavis[4726]: (04726-02) G7i34mNU8cq2 FWD from
<a.user at domain.com> -> <someone at 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.user at domain.com> -> <someone at 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
More information about the amavis-users
mailing list