Delays in mail deliveries

Wed Mar 2 17:12:28 CET 2022

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 at RD501AC5C3338C>
Mar  2 15:28:47 mailgw1 postfix/qmgr[1253942]: 4K7w1W6F77zMMYt: 
from=<no-reply at sharepointonline.com>, 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=<userxxxx at noa.gr>, 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: 
<no-reply at sharepointonline.com>, a=rsa-sha256, c=relaxed/relaxed, 
s=selector1-spoemeaeop-onmicrosoft-com, i=@spoemeaeop.onmicrosoft.com
Mar  2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) dkim: policy 
bank WHITELIST,NOBANNEDCHECK,NOVIRUSCHECK by no-reply at sharepointonline.com
Mar  2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) dkim: VALID 
Author+Sender+MailFrom signature by d=sharepointonline.com, From: 
<no-reply at sharepointonline.com>, a=rsa-sha256, c=relaxed/relaxed, 
s=selector1, i=@sharepointonline.com
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] 
<no-reply at sharepointonline.com> -> <userxxxx at noa.gr>
Mar  2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) 2822.From: 
<no-reply at sharepointonline.com>, 2822.Sender: 
<no-reply at sharepointonline.com>
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: userxxxx at noa.gr
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:<no-reply at sharepointonline.com> BODY=7BIT
Mar  2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) smtp cmd> RCPT 
TO:<userxxxx at noa.gr> ORCPT=rfc822;userxxxx at noa.gr 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) (<userxxxx at noa.gr>): 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 (<userxxxx at noa.gr>): 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 <no-reply at sharepointonline.com> -> <userxxxx at noa.gr>, 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, <no-reply at sharepointonline.com>
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] <no-reply at sharepointonline.com> -> <userxxxx at noa.gr>, 
Message-ID: 
<odspmicro-SpoShare-e5cf25a0-d0ea-c000-b666-025e9e385410-1aa7b39f-88ac-4fd9-89dd-afb9eb36dccb-13168c28-f663-4e5f-bda9-1782c685117f at RD501AC5C3338C>, 
mail_id: CBhdqtu9BU97, Hits: -, size: 11575, 589 ms
Mar  2 15:30:47 mailgw1 amavis[1254468]: (1254468-09-16) LMTP response 
for <userxxxx at noa.gr>: "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 at RD501AC5C3338C>
Mar  2 15:30:47 mailgw1 postfix/qmgr[1253942]: 4K7w3q6jL2zMMYV: 
from=<no-reply at sharepointonline.com>, size=12203, nrcpt=1 (queue active)
Mar  2 15:35:48 mailgw1 postfix/smtp[1255336]: 4K7w3q6jL2zMMYV: 
to=<userxxxx at noa.gr>, 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