On Wed, Jun 08, 2022 at 03:56:20PM +0300, Nikolaos Milas wrote:
> Jun 08 11:48:29 mailgw1 postfix/smtpd[379212]: connect from
> o5.email.wetransfer.com[167.89.35.243]
> Jun 08 11:48:30 mailgw1 postfix/smtpd[379212]: Anonymous TLS connection
> established from o5.email.wetransfer.com[167.89.35.243]: TLSv1.3 with
> cipher TLS_AES_128_GCM_SHA256 (128/128 bits) key-exchange X25519
> server-signature RSA-PSS (4096 bits) server-digest SHA256
> Jun 08 11:48:31 mailgw1 postfix/smtpd[379212]: 4LJ18v2F3zzM587:
> client=o5.email.wetransfer.com[167.89.35.243]
> Jun 08 11:48:31 mailgw1 postfix/cleanup[380438]: 4LJ18v2F3zzM587:
> message-id=<wtm.6c964765-fb3a-4ed8-9e8b-211443c23...@wetransfer.com>
> Jun 08 11:48:31 mailgw1 postfix/qmgr[372611]: 4LJ18v2F3zzM587:
> from=<bounces+922094-d8d5-userx=noa...@em9713.email.wetransfer.com>,
> size=43976, nrcpt=1 (queue active)
> Jun 08 11:48:32 mailgw1 postfix/smtpd[379212]: disconnect from
> o5.email.wetransfer.com[167.89.35.243] ehlo=2 starttls=1 mail=1 rcpt=1
> data=1 quit=1 commands=7
> Jun 08 11:48:33 mailgw1 postfix/lmtp[380474]: 4LJ18v2F3zzM587:
> to=<us...@noa.gr>, relay=127.0.0.1[127.0.0.1]:10024, delay=2.7,
> delays=1.3/0/0/1.4, 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 4LJ18x2TQSzM58J)
> Jun 08 11:48:33 mailgw1 postfix/qmgr[372611]: 4LJ18v2F3zzM587: removed
This hop did not introduce any significant delays.
> Jun 08 11:48:33 mailgw1 postfix/smtpd[379124]: connect from
> localhost[127.0.0.1]
> Jun 08 11:48:33 mailgw1 postfix/smtpd[379124]: 4LJ18x2TQSzM58J:
> client=localhost[127.0.0.1]
> Jun 08 11:48:33 mailgw1 postfix/cleanup[380469]: 4LJ18x2TQSzM58J:
> message-id=<wtm.6c964765-fb3a-4ed8-9e8b-211443c23...@wetransfer.com>
> Jun 08 11:48:33 mailgw1 postfix/qmgr[372611]: 4LJ18x2TQSzM58J:
> from=<bounces+922094-d8d5-userx=noa...@em9713.email.wetransfer.com>,
> size=44853, nrcpt=1 (queue active)
> Jun 08 11:48:33 mailgw1 postfix/smtpd[379124]: disconnect from
> localhost[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
> Jun 08 11:52:48 mailgw1 postfix/smtp[380422]: 4LJ18x2TQSzM58J:
> to=<us...@noa.gr>, relay=vmail2.noa.gr[2001:648:2011:15::166]:25,
> delay=255, delays=0.01/0/0.05/255, dsn=2.0.0, status=sent (250 2.0.0 Ok:
> queued as 671E9804DEE08)
> Jun 08 11:52:48 mailgw1 postfix/qmgr[372611]: 4LJ18x2TQSzM58J: removed
This hop incurred a delay during message transmission to the remote
server.
> Jun 08 11:48:33 vmail2 postfix/smtpd[10619]: connect from
> mailgw1.noa.gr[2001:648:2ffc:1115::27]
> Jun 08 11:48:33 vmail2 postfix/smtpd[10619]: Anonymous TLS connection
> established from mailgw1.noa.gr[2001:648:2ffc:1115::27]: TLSv1.3 with
> cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-
> exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256
> Jun 08 11:48:33 vmail2 postfix/smtpd[10619]: 671E9804DEE08:
> client=mailgw1.noa.gr[2001:648:2ffc:1115::27]
> Jun 08 11:48:33 vmail2 postfix/cleanup[10742]: 671E9804DEE08:
> message-id=<wtm.6c964765-fb3a-4ed8-9e8b-211443c23...@wetransfer.com>
The envelope and message headers were received promptly.
> Jun 08 11:52:48 vmail2 postfix/qmgr[30346]: 671E9804DEE08:
> from=<bounces+922094-d8d5-userx=noa...@em9713.email.wetransfer.com>,
> size=45294, nrcpt=1 (queue active)
The delay was in processing the message body and/or alerting the queue
manager to the arrival of the new message. Are you using milters that
query remote oracles (perhaps DNS?) in order to determine whether the
message content is acceptable? Perhaps there are many URLs in the
message that result in many slow remote lookups?
> Jun 08 11:52:48 vmail2 postfix/smtpd[10619]: disconnect from
> mailgw1.noa.gr[2001:648:2ffc:1115::27] ehlo=2 starttls=1 mail=1 rcpt=1
> data=1 quit=1 commands=7
Either transmission was slow, or body processing (milters, header
checks, body checks, ...) was slow, since the SMTP dialogue ended
late. If the queue is draining slowly, this could be related to
"inflow_delay" kicking in when message arrival outpaces delivery.
> Jun 08 11:52:48 vmail2 postfix/lmtp[17935]: 671E9804DEE08:
> to=<us...@noa.gr>, relay=vmail2.noa.gr[private/dovecot-lmtp], delay=255,
> delays=255/0.003/0.001/0.016, dsn=2.0.0, status=sent (250 2.0.0
> <us...@noa.gr> SIJZCWBjoGIQRgAAcV+qjQ Saved)
> Jun 08 11:52:48 vmail2 postfix/qmgr[30346]: 671E9804DEE08: removed
The rest looks OK.
> Jun 08 12:23:44 mailgw1 postfix/smtp[380547]: 4LJ1rd2yxSzM58b:
> to=<us...@noa.gr>, relay=vmail2.noa.gr[194.177.195.166]:25, delay=255,
> delays=0.01/0/0.06/255, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as
> 78A6683DB31BD)
A consistent 255s delay feels like some sort of timeout...
> smtpd_end_of_data_restrictions = check_client_access
> cidr:/etc/postfix/postfwdpolicy.cidr
Could this be slow?
> milter_default_action = accept
> non_smtpd_milters = $smtpd_milters
> smtpd_milters = inet:127.0.0.1:8891
What does this milter do?
--
Viktor.
