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]

Reply via email to