Hi,
Just wanted to say thanks for the help and input and while I never
really solved the issue, I jumped up to use v2.4.2 instead and at lest
then I didn't have this issue anymore.
//Kim
On 2026-01-24 10:03, John Fawcett via dovecot wrote:
Hi Kim
of course anything could be possible, but I personally am not convinced
that Dovecot is blocking or failing with a "451 4.3.0 Temporary internal
error" to Postfix without logging (before or after that response and
somewhere during the lmtp transaction) something more specific in
Dovecot's own logging.
Only other things that come to mind, unless you want to post more details,
are:
1. check how you are enabling debugging output in dovecot in case you have
enabled it selectively and are not seeing the full picture. I have to say
that this might not be a particularly likely avenue to follow since from
my knowledge of the code I am expecting Dovecot to log an error message,
but it could be worth a try if all else is failing to shed light on the
cause.
2. if you have a working installation somewhere, you could compare the
debug logging of Dovecot on a similar working transaction and that might
give you a clue as to what is happening that is different in this case.
3. Coming at the problem from a different angle, you could enable
verbosity in the Postfix lmtp client by adding a -v parameter to the lmtp
service in master.cf (where this is a server on which you can safely do
debugging and troubleshooting)
lmtp unix - - n - - lmtp -v
That will enable you to see the whole lmtp transaction from Postfix's
point of view and may provide an alternative insight in to what is
happening. One thing to notice (since you were mentioning that the error
is happening after the DATA stage) is that if Dovecot is announcing
PIPELINING support and Postfix is using it (both these are as expected -
see example below), then Postfix arrives at sending the DATA command
before Dovecot has responded on the sender and recipients(s).
Jan 24 09:36:52 server.example.com postfix/lmtp[1951890]:
smtp_connect_unix: trying: private/dovecot-lmtp... Jan 24 09:36:52
server.example.com postfix/lmtp[1951890]: smtp_stream_setup: maxtime=300
enable_deadline=0 min_data_rate=0 Jan 24 09:36:52 server.example.com
postfix/lmtp[1951890]: < server.example.com[private/dovecot-lmtp]: 220
server.example.com Dovecot ready. Jan 24 09:36:52 server.example.com
postfix/lmtp[1951890]: > server.example.com[private/dovecot-lmtp]: LHLO
server.example.com Jan 24 09:36:52 server.example.com
postfix/lmtp[1951890]: < server.example.com[private/dovecot-lmtp]:
250-server.example.com Jan 24 09:36:52 server.example.com
postfix/lmtp[1951890]: < server.example.com[private/dovecot-lmtp]:
250-8BITMIME Jan 24 09:36:52 server.example.com postfix/lmtp[1951890]: <
server.example.com[private/dovecot-lmtp]: 250-CHUNKING Jan 24 09:36:52
server.example.com postfix/lmtp[1951890]: <
server.example.com[private/dovecot-lmtp]: 250-ENHANCEDSTATUSCODES Jan 24
09:36:52 server.example.com postfix/lmtp[1951890]: <
server.example.com[private/dovecot-lmtp]: 250-PIPELINING Jan 24 09:36:52
server.example.com postfix/lmtp[1951890]: <
server.example.com[private/dovecot-lmtp]: 250 STARTTLS Jan 24 09:36:52
server.example.com postfix/lmtp[1951890]: server features: 0x17 size 0 Jan
24 09:36:52 server.example.com postfix/lmtp[1951890]: Using LMTP
PIPELINING, TCP send buffer size is 212992, PIPELINING buffer size is 4096
Jan 24 09:36:52 server.example.com postfix/lmtp[1951890]:
smtp_stream_setup: maxtime=300 enable_deadline=0 min_data_rate=0 Jan 24
09:36:52 server.example.com postfix/lmtp[1951890]: >
server.example.com[private/dovecot-lmtp]: MAIL
FROM:[1]<[email protected]> BODY=7BIT Jan 24 09:36:52 server.example.com
postfix/lmtp[1951890]: > server.example.com[private/dovecot-lmtp]: RCPT
TO:[2]<[email protected]> Jan 24 09:36:52 server.example.com
postfix/lmtp[1951890]: > server.example.com[private/dovecot-lmtp]: DATA
Jan 24 09:36:52 server.example.com postfix/lmtp[1951890]:
smtp_stream_setup: maxtime=300 enable_deadline=0 min_data_rate=0 Jan 24
09:36:52 server.example.com postfix/lmtp[1951890]: <
server.example.com[private/dovecot-lmtp]: 250 2.1.0 OK Jan 24 09:36:52
server.example.com postfix/lmtp[1951890]: smtp_stream_setup: maxtime=300
enable_deadline=0 min_data_rate=0 Jan 24 09:36:52 server.example.com
postfix/lmtp[1951890]: < server.example.com[private/dovecot-lmtp]: 250
2.1.5 OK Jan 24 09:36:52 server.example.com postfix/lmtp[1951890]:
smtp_stream_setup: maxtime=120 enable_deadline=0 min_data_rate=0 Jan 24
09:36:52 server.example.com postfix/lmtp[1951890]: <
server.example.com[private/dovecot-lmtp]: 354 OK Jan 24 09:36:52
server.example.com postfix/lmtp[1951890]: smtp_stream_setup: maxtime=180
enable_deadline=0 min_data_rate=500 Jan 24 09:36:52 server.example.com
postfix/lmtp[1951890]: > server.example.com[private/dovecot-lmtp]: . Jan
24 09:36:52 server.example.com postfix/lmtp[1951890]: >
server.example.com[private/dovecot-lmtp]: QUIT Jan 24 09:36:52
server.example.com postfix/lmtp[1951890]: smtp_stream_setup: maxtime=600
enable_deadline=0 min_data_rate=0 Jan 24 09:36:52 server.example.com
postfix/lmtp[1951890]: < server.example.com[private/dovecot-lmtp]: 250
2.0.0 [3]<[email protected]> sbrTDqSEdGmTyB0ALVh/mg Saved Jan 24
09:36:52 server.example.com postfix/lmtp[1951890]: 4dyp7S1Qxyz1q919:
to=[4]<[email protected]>,
relay=server.example.com[private/dovecot-lmtp], delay=0.13,
delays=0/0.01/0.03/0.08, dsn=2.0.0, status=sent (250 2.0.0
[5]<[email protected]> sbrTDqSEdGmTyB0ALVh/mg Saved) Jan 24 09:36:52
server.example.com postfix/lmtp[1951890]: smtp_loop: got 1 of 1
end-of-data replies Jan 24 09:36:52 server.example.com
postfix/lmtp[1951890]: smtp_stream_setup: maxtime=300 enable_deadline=0
min_data_rate=0 Jan 24 09:36:52 server.example.com postfix/lmtp[1951890]:
< server.example.com[private/dovecot-lmtp]: 221 2.0.0 Bye
John
On 23/01/2026 09:40, Kim Haverblad via dovecot wrote:
Hi John,
thank you for the clarification -- that helps, and I agree that the
auth-worker disconnect message itself can be disregarded.
To narrow this down further, the consistent behavior I'm seeing is that
everything succeeds up to the point where Dovecot should write the message
to disk, but the actual mailbox write never happens.
What works
o LMTP connection is established
o RCPT is accepted
o userdb lookup succeeds and returns:
o valid mailbox path under /var/mail/vmail/
o explicit uid/gid
o quota rule
o No errors are logged during authentication or userdb lookup
What fails
o After the DATA phase, Postfix receives:
"451 4.3.0 Temporary internal error"
o No message is written to disk
o No Maildir structure (cur/, new/, tmp/) is created automatically
o Manually creating /var/mail/vmail/<domain>/<user>/ (including Maildir
structure) does not change the behavior
What has been verified
o Ownership and permissions on /var/mail/vmail and subdirectories match
the uid/gid returned by userdb
o Parent directories are writable
o Disk space and inodes are available
o This is a local filesystem (no NFS)
o The problem persists even with a freshly created mailbox path
From this, it appears that Dovecot is blocked or failing internally at the
final delivery/write stage, but without emitting a more specific error
message.
//Kim
On 2026-01-23 09:12, John Fawcett via dovecot wrote:
On 22/01/2026 20:57, Kim Haverblad via dovecot wrote:
Hi dovecot list,
I'm troubleshooting an LMTP delivery issue with Dovecot and would
appreciate clarification on the meaning and impact of the
following log
message, which appears repeatedly during delivery attempts:
auth-worker(2961): Debug: conn unix:auth-worker
(pid=2948,uid=107):
Disconnected: Connection closed (fd=-1)
Environment
o OS: Ubuntu (latest LTS, fully up to date)
o Dovecot: distribution package (current version for Ubuntu)
o MTA: Postfix
o Delivery: LMTP to Dovecot
o User database: MySQL (userdb lookup succeeds)
o Mail storage: Maildir
o Quotas: enabled via userdb (quota_rule)
Context
o LMTP accepts the recipient and completes userdb lookup
successfully.
o The mailbox path, uid, gid, and quota are correctly returned.
o Postfix later receives a 451 4.3.0 Temporary internal error
after the
DATA phase.
o The above auth-worker ... Disconnected: Connection closed
(fd=-1)
message appears around the same time.
Questions
1. Is this Disconnected: Connection closed (fd=-1) message
expected/normal behavior for auth-worker processes once a
lookup is
complete?
2. Under what circumstances would this indicate a real problem
versus a
harmless connection teardown?
3. Could this message itself contribute to, or explain, LMTP 451
4.3.0
Temporary internal error responses?
4. Are there specific auth-worker, LMTP, or debug settings
recommended to
determine whether this disconnect is abnormal?
So far, authentication and userdb lookups appear clean, and there
are no
explicit permission or quota errors logged, which makes it unclear
whether
this message is relevant to the delivery failure or simply
informational.
Any clarification on how to interpret this log entry -- and how to
confirm
whether it is benign or problematic -- would be greatly
appreciated.
Kind Regards,
Kim
Hi Kim
that's a debug message. In an installation running without debug logging
you never get to see it. I cannot think of any reason why that message
should be considered an issue. Certainly the 451 error message is much
more indicative of a problem. Also since the error message is happening
after the DATA phase, I would look for an issue that does not occur in
the auth-worker process (even if it potentially could be triggered by
data returned in the user lookups).
If you post the logging of the complete LMTP transaction to the list
someone may be able to identify something else that looks strange. The
info in your email contains little clue to the cause. If privacy is a
concern you can consistently modify email addresses throughout the log
snippet. dovecot -n output could also help too.
John
_______________________________________________
dovecot mailing list -- [[6]1][email protected]
To unsubscribe send an email to [[7]2][email protected]
References
Visible links
1. [8]mailto:[email protected]
2. [9]mailto:[email protected]
_______________________________________________
dovecot mailing list -- [10][email protected]
To unsubscribe send an email to [11][email protected]
References
Visible links
1. mailto:[email protected]
2. mailto:[email protected]
3. mailto:[email protected]
4. mailto:[email protected]
5. mailto:[email protected]
6. mailto:1][email protected]
7. mailto:2][email protected]
8. mailto:[email protected]
9. mailto:[email protected]
10. mailto:[email protected]
11. mailto:[email protected]
_______________________________________________
dovecot mailing list -- [email protected]
To unsubscribe send an email to [email protected]
_______________________________________________
dovecot mailing list -- [email protected]
To unsubscribe send an email to [email protected]
