Meaning of auth-worker disconnected message and relation to LMTP 451 errors on Ubuntu
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*
- OS: Ubuntu (latest LTS, fully up to date)
- Dovecot: distribution package (current version for Ubuntu)
- MTA: Postfix
- Delivery: LMTP to Dovecot
- User database: MySQL (userdb lookup succeeds)
- Mail storage: Maildir
- Quotas: enabled via userdb (quota_rule)
*Context*
- LMTP accepts the recipient and completes userdb lookup successfully.
- The mailbox path, uid, gid, and quota are correctly returned.
- Postfix later receives a 451 4.3.0 Temporary internal error after the DATA phase.
- The above auth-worker ... Disconnected: Connection closed (fd=-1)message appears around the same time.
*Questions*
- Is this Disconnected: Connection closed (fd=-1) message expected/normal behavior for auth-worker processes once a lookup is complete?
- Under what circumstances would this indicate a real problem versus a harmless connection teardown?
- Could this message itself contribute to, or explain, LMTP 451 4.3.0 Temporary internal error responses?
- 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 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
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
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*
- LMTP connection is established
- RCPT is accepted
- userdb lookup succeeds and returns: o valid mailbox path under /var/mail/vmail/ o explicit uid/gid o quota rule
- No errors are logged during authentication or userdb lookup
*What fails*
- After the DATA phase, Postfix receives:
"451 4.3.0 Temporary internal error"
- No message is written to disk
- No Maildir structure (cur/, new/, tmp/) is created automatically
- Manually creating /var/mail/vmail/<domain>/<user>/ (including Maildir structure) does not change the behavior
*What has been verified*
- Ownership and permissions on /var/mail/vmail and subdirectories match the uid/gid returned by userdb
- Parent directories are writable
- Disk space and inodes are available
- This is a local filesystem (no NFS)
- 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 -- dovecot@dovecot.org To unsubscribe send an email to dovecot-leave@dovecot.org
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 lookupWhat 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 behaviorWhat 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 pathFrom 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 -- [1]dovecot@dovecot.org
To unsubscribe send an email to [2]dovecot-leave@dovecot.orgReferences
Visible links
- mailto:dovecot@dovecot.org
- mailto:dovecot-leave@dovecot.org
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:
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.
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.
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:<someone@example.com> BODY=7BIT Jan 24 09:36:52 server.example.com postfix/lmtp[1951890]: > server.example.com[private/dovecot-lmtp]: RCPT TO:<someoneelse@example.com> 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 <someoneelse@example.com> sbrTDqSEdGmTyB0ALVh/mg Saved Jan 24 09:36:52 server.example.com postfix/lmtp[1951890]: 4dyp7S1Qxyz1q919: to=<someoneelse@example.com>, 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 <someoneelse@example.com> 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 -- [1]dovecot@dovecot.org To unsubscribe send an email to [2]dovecot-leave@dovecot.orgReferences
Visible links 1.mailto:dovecot@dovecot.org 2.mailto:dovecot-leave@dovecot.org
dovecot mailing list --dovecot@dovecot.org To unsubscribe send an email todovecot-leave@dovecot.org
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:
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.
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.
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]<someone@example.com> BODY=7BIT Jan 24 09:36:52 server.example.com postfix/lmtp[1951890]: > server.example.com[private/dovecot-lmtp]: RCPT TO:[2]<someoneelse@example.com> 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]<someoneelse@example.com> sbrTDqSEdGmTyB0ALVh/mg Saved Jan 24 09:36:52 server.example.com postfix/lmtp[1951890]: 4dyp7S1Qxyz1q919: to=[4]<someoneelse@example.com>, 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]<someoneelse@example.com> 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]dovecot@dovecot.org
To unsubscribe send an email to [[7]2]dovecot-leave@dovecot.orgReferences
Visible links
1. [8]mailto:dovecot@dovecot.org
2. [9]mailto:dovecot-leave@dovecot.org_______________________________________________ dovecot mailing list -- [10]dovecot@dovecot.org To unsubscribe send an email to [11]dovecot-leave@dovecot.org
References
Visible links
- mailto:someone@example.com
- mailto:someoneelse@example.com
- mailto:someoneelse@example.com
- mailto:someoneelse@example.com
- mailto:someoneelse@example.com
- mailto:1]dovecot@dovecot.org
- mailto:2]dovecot-leave@dovecot.org
- mailto:dovecot@dovecot.org
- mailto:dovecot-leave@dovecot.org
- mailto:dovecot@dovecot.org
- mailto:dovecot-leave@dovecot.org
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]<someone@example.com> BODY=7BIT Jan 24 09:36:52 server.example.com postfix/lmtp[1951890]: > server.example.com[private/dovecot-lmtp]: RCPT TO:[2]<someoneelse@example.com> 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]<someoneelse@example.com> sbrTDqSEdGmTyB0ALVh/mg Saved Jan 24 09:36:52 server.example.com postfix/lmtp[1951890]: 4dyp7S1Qxyz1q919: to=[4]<someoneelse@example.com>, 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]<someoneelse@example.com> 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]dovecot@dovecot.org To unsubscribe send an email to [[7]2]dovecot-leave@dovecot.orgReferences
Visible links 1. [8]mailto:dovecot@dovecot.org 2. [9]mailto:dovecot-leave@dovecot.org_______________________________________________ dovecot mailing list -- [10]dovecot@dovecot.org To unsubscribe send an email to [11]dovecot-leave@dovecot.org
References
Visible links 1. mailto:someone@example.com 2. mailto:someoneelse@example.com 3. mailto:someoneelse@example.com 4. mailto:someoneelse@example.com 5. mailto:someoneelse@example.com 6. mailto:1]dovecot@dovecot.org 7. mailto:2]dovecot-leave@dovecot.org 8. mailto:dovecot@dovecot.org 9. mailto:dovecot-leave@dovecot.org10. mailto:dovecot@dovecot.org 11. mailto:dovecot-leave@dovecot.org
dovecot mailing list -- dovecot@dovecot.org To unsubscribe send an email to dovecot-leave@dovecot.org
participants (2)
-
John Fawcett
-
Kim Haverblad