On 2/3/2022 5:27 μ.μ., Damian wrote:
As Bastian pointed out, your mail sample passed Amavis within a few
seconds. If those received timings are typical for your problem,
forget about micro-optimizing Amavis.
You are right Damian and Bastian.
I include here the actual logs of one such session (only mail local part
has been changed):
Phase 1: Postfix receives mail from the Internet (auto collated)
Mar 2 15:28:47 mailgw1 postfix/smtpd[1255009]: connect from
mail-eopbgr40130.outbound.protection.outlook.com[40.107.4.130]
Mar 2 15:28:47 mailgw1 postfix/smtpd[1255009]: Anonymous TLS connection
established from
mail-eopbgr40130.outbound.protection.outlook.com[40.107.4.130]: TLSv1.2
with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
Mar 2 15:28:47 mailgw1 postfix/smtpd[1255009]: 4K7w1W6F77zMMYt:
client=mail-eopbgr40130.outbound.protection.outlook.com[40.107.4.130]
Mar 2 15:28:47 mailgw1 postfix/cleanup[1255000]: 4K7w1W6F77zMMYt:
message-id=<odspmicro-SpoShare-e5cf25a0-d0ea-c000-b666-025e9e385410-1aa7b39f-88ac-4fd9-89dd-afb9eb36dccb-13168c28-f663-4e5f-bda9-1782c685117f@RD501AC5C3338C>
Mar 2 15:28:47 mailgw1 postfix/qmgr[1253942]: 4K7w1W6F77zMMYt:
from=<[email protected]>, size=11595, nrcpt=1 (queue active)
Mar 2 15:28:48 mailgw1 postfix/smtpd[1255009]: disconnect from
mail-eopbgr40130.outbound.protection.outlook.com[40.107.4.130] ehlo=2
starttls=1 mail=1 rcpt=1 bdat=1 quit=1 commands=7
Mar 2 15:30:47 mailgw1 postfix/lmtp[1254999]: 4K7w1W6F77zMMYt:
to=<[email protected]>, relay=127.0.0.1[127.0.0.1]:10024, conn_use=16,
delay=120, delays=0.39/119/0/0.59, dsn=2.0.0, status=sent (250 2.0.0
from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 4K7w3q6jL2zMMYV)
Mar 2 15:30:47 mailgw1 postfix/qmgr[1253942]: 4K7w1W6F77zMMYt: removed
Phase 2: Amavis receives from Postfix, processes and delivers back to
Postfix
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) body hash:
3c3a7d7aef31b9cbbceab17a9be9f47c
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) trace:
UTF8LMTP://[127.0.0.1]:42650 < ESMTPS://40.107.4.130 <
Microsoft_SMTP_Server://x < Microsoft_SMTP_Server://x <
Microsoft_SMTP_Server://52.232.126.143
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) dkim: VALID
third-party signature by d=spoemeaeop.onmicrosoft.com, From:
<[email protected]>, a=rsa-sha256, c=relaxed/relaxed,
s=selector1-spoemeaeop-onmicrosoft-com, [email protected]
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) dkim: policy
bank WHITELIST,NOBANNEDCHECK,NOVIRUSCHECK by [email protected]
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) dkim: VALID
Author+Sender+MailFrom signature by d=sharepointonline.com, From:
<[email protected]>, a=rsa-sha256, c=relaxed/relaxed,
s=selector1, [email protected]
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) loaded policy
bank "WHITELIST"
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) loaded policy
bank "NOBANNEDCHECK" over "WHITELIST"
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) loaded policy
bank "NOVIRUSCHECK" over "WHITELIST/NOBANNEDCHECK"
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) client IP
address unknown, fetched from Received: 127.0.0.1
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) Checking:
CBhdqtu9BU97 WHITELIST/NOBANNEDCHECK/NOVIRUSCHECK [127.0.0.1]
<[email protected]> -> <[email protected]>
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) 2822.From:
<[email protected]>, 2822.Sender:
<[email protected]>
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) Checking for
banned types and filenames
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) skipping banned
check: all recipients bypass banned checks
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16)
do_notify_and_quar: ccat=Clean (1,0) ("1":Clean, "0":CatchAll)
ccat_block=(), qar_mth=
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) delivery method
is 1, recips: [email protected]
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) smtp session
reuse (smtp:[127.0.0.1]:10025), 13 transactions so far
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) smtp session
most likely still valid (short idle 0.6 s)
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) AUTH not
needed, user='', MTA offers ''
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) smtp cmd> MAIL
FROM:<[email protected]> BODY=7BIT
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) smtp cmd> RCPT
TO:<[email protected]> ORCPT=rfc822;[email protected] NOTIFY=NEVER
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) smtp cmd> DATA
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) smtp resp to
MAIL (pip): 250 2.1.0 Ok
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) smtp resp to
RCPT (pip) (<[email protected]>): 250 2.1.5 Ok
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) smtp resp to
DATA: 354 End data with <CR><LF>.<CR><LF>
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) smtp resp to
data-dot (<[email protected]>): 250 2.0.0 Ok: queued as 4K7w3q6jL2zMMYV,
dt: 6.8 ms
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16)
Amavis::Out::SMTP::Session close, keeping connection
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) CBhdqtu9BU97
FWD from <[email protected]> -> <[email protected]>, BODY=7BIT
250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as
4K7w3q6jL2zMMYV
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) DSN: sender is
credible (dkim), SA: 0.000, <[email protected]>
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) status
counters: InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedInbound}
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) Passed CLEAN
{RelayedInbound}, WHITELIST/NOBANNEDCHECK/NOVIRUSCHECK [127.0.0.1]
[52.232.126.143] <[email protected]> -> <[email protected]>,
Message-ID:
<odspmicro-SpoShare-e5cf25a0-d0ea-c000-b666-025e9e385410-1aa7b39f-88ac-4fd9-89dd-afb9eb36dccb-13168c28-f663-4e5f-bda9-1782c685117f@RD501AC5C3338C>,
mail_id: CBhdqtu9BU97, Hits: -, size: 11575, 589 ms
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) LMTP response
for <[email protected]>: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250
2.0.0 Ok: queued as 4K7w3q6jL2zMMYV"
Mar 2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) size: 11575,
TIMING [total 601 ms] - SMTP MAIL: 0.7 (0%)0, SMTP pre-DATA-flush: 0.8
(0%)0, SMTP DATA: 40 (7%)7, check_init: 0.3 (0%)7, digest_hdr: 2.4
(0%)7, digest_body_dkim: 458 (76%)84, collect_info: 22 (4%)87,
check_header: 1.1 (0%)87, decide_mail_destiny: 0.4 (0%)88, notif-quar:
0.3 (0%)88, fwd-connect: 25 (4%)92, fwd-mail-pip: 1.7 (0%)92,
fwd-rcpt-pip: 0.2 (0%)92, fwd-data-chkpnt: 0.0 (0%)92, write-header: 0.6
(0%)92, fwd-data-contents: 24 (4%)96, fwd-end-chkpnt: 8 (1%)98,
prepare-dsn: 0.6 (0%)98, report: 0.9 (0%)98, main_log_entry: 1.7 (0%)98,
update_snmp: 0.7 (0%)98, SMTP pre-response: 0.2 (0%)98, SMTP response:
0.2 (0%)98, rundown: 11 (2%)100
Phase 3: Postfix receives back from Amavis and forwards to final
destination (auto collated)
Mar 2 15:28:52 mailgw1 postfix/smtpd[1254591]: connect from
localhost[127.0.0.1]
Mar 2 15:28:52 mailgw1 postfix/smtpd[1254591]: 4K7w1c6zw0zMMYY:
client=localhost[127.0.0.1]
Mar 2 15:28:53 mailgw1 postfix/smtpd[1254591]: 4K7w1d2S7fzMMYY:
client=localhost[127.0.0.1]
Mar 2 15:28:53 mailgw1 postfix/smtpd[1254591]: 4K7w1d6khZzMMYc:
client=localhost[127.0.0.1]
Mar 2 15:28:54 mailgw1 postfix/smtpd[1254591]: 4K7w1f0qrgzMMYY:
client=localhost[127.0.0.1]
Mar 2 15:28:54 mailgw1 postfix/smtpd[1254591]: 4K7w1f21hPzMMYc:
client=localhost[127.0.0.1]
Mar 2 15:29:01 mailgw1 postfix/smtpd[1254591]: 4K7w1n1J0wzMMYY:
client=localhost[127.0.0.1]
Mar 2 15:29:19 mailgw1 postfix/smtpd[1254591]: 4K7w270k2GzMMYf:
client=localhost[127.0.0.1]
Mar 2 15:29:21 mailgw1 postfix/smtpd[1254591]: 4K7w2959DyzMMYd:
client=localhost[127.0.0.1]
Mar 2 15:29:24 mailgw1 postfix/smtpd[1254591]: 4K7w2D0KMfzMMYf:
client=localhost[127.0.0.1]
Mar 2 15:30:44 mailgw1 postfix/smtpd[1254591]: 4K7w3m1jQfzMMYP:
client=localhost[127.0.0.1]
Mar 2 15:30:44 mailgw1 postfix/smtpd[1254591]: 4K7w3m3nvDzMMYV:
client=localhost[127.0.0.1]
Mar 2 15:30:46 mailgw1 postfix/smtpd[1254591]: 4K7w3p1xwCzMMYG:
client=localhost[127.0.0.1]
Mar 2 15:30:47 mailgw1 postfix/smtpd[1254591]: 4K7w3q2hGyzMMYP:
client=localhost[127.0.0.1]
Mar 2 15:30:47 mailgw1 postfix/smtpd[1254591]: 4K7w3q6jL2zMMYV:
client=localhost[127.0.0.1]
Mar 2 15:30:47 mailgw1 postfix/cleanup[1254592]: 4K7w3q6jL2zMMYV:
message-id=<odspmicro-SpoShare-e5cf25a0-d0ea-c000-b666-025e9e385410-1aa7b39f-88ac-4fd9-89dd-afb9eb36dccb-13168c28-f663-4e5f-bda9-1782c685117f@RD501AC5C3338C>
Mar 2 15:30:47 mailgw1 postfix/qmgr[1253942]: 4K7w3q6jL2zMMYV:
from=<[email protected]>, size=12203, nrcpt=1 (queue active)
Mar 2 15:35:48 mailgw1 postfix/smtp[1255336]: 4K7w3q6jL2zMMYV:
to=<[email protected]>, relay=vmail2.noa.gr[194.177.195.166]:25,
delay=300, delays=0.03/0.02/0.05/300, dsn=2.0.0, status=sent (250 2.0.0
Ok: queued as 14A6C809703C1)
Mar 2 15:35:48 mailgw1 postfix/qmgr[1253942]: 4K7w3q6jL2zMMYV: removed
That shows indeed that amavis completes very quickly.
But why does Postfix delay so much in delivering, both at Phase 1 and 3?
Thanks,
Nick
