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