Nikolaos Milas:
mailgw1 receives mail from a content filter, and delivers it to vmail2.
> 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
Above, there is a delay of 4 minutes between receiving email, and
completion of delivery via SMTP to vmail2.
The logging below shows that the SMTP session starts immediately
after mailgw1 receives the email message. Theerfore the delay is
either in the mailgw1 SMTP client, in the network between mailgw1
and vmail2, or somewhere in vmail2.
> On vmail2.noa.gr:
>
> 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>
Up to this point there is no delay: the vmail2 SMTP server immediately
accepts the connection, accepts an RCPT TO command, and the cleanup
daemon immediately logs the message-id header.
HOWEVER, the SMTP session from mailgw1 to vmail2 stays open for 4+
minutes, i.e. the vmail2 SMTP server does not yet reply to "."
(end of message) and the mailgw1 SMTP client does not disconnect.
Four minutes later, the vmail2 SMTP server replies to ".", the
mailgw1 SMTP client disconnects, and the queue manager receives a
message from the cleanup daemon that the queue file is ready for
delivery.
> 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)
> 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
[and the messaage is delivered to Dovecot]
Possible causes (there may be more):
- There is a problem with the network connection between mailgw1
and mailgw1 that causes some connections to have excessive retries.
This could be a data-dependent problem. About 20 years ago, someone
fixed a Postfix networking problem by replacing bad network hardware
(a different port on a switch).
- There is a problem in the file system that causes delays in the
fsync() system call. Postfix will not reply that the mesasage has
been "received" before that system call completes successfully. If
you are using a networked file system, see my previous point. fsync()
performance also depends on how a disk drive manages its cache.
- vmail2 is using header_checks, body_checks, or smtpd_milters that
take an insane amount of time. These are by their nature data-dependent.
Sorry, no time to examine up your Postfix configuration.
For now, my money is on the fsync() call.
Wietse
