Outbox message re-sent on every background job run when IMAP LOGOUT fails (exception in `finally` discards the send state)

[bigthib0]

Steps to reproduce

Precondition: any IMAP failure during the "copy to Sent" APPEND that leaves the connection unusable, so the subsequent $client->logout() throws. The Nextcloud-side defect described below is independent of why the IMAP call fails.

What triggered it for us: enabling mail_utf8_extensions = yes globally on Dovecot 2.4.1. From that moment every Nextcloud Mail "copy to Sent" and draft APPEND failed. Dovecot logged the command as finished having received only the ~76–85 byte command line and never the message literal (in=76 out=670), and the client threw a read timeout ~125 s later. Scoping the setting to protocol lmtp { mail_utf8_extensions = yes } restored normal behaviour immediately.

We did not capture the wire-level IMAP dialog, so we cannot say what Dovecot actually replied. A similar APPEND failure against Dovecot 2.4 with this setting was reported for Thunderbird in https://bugzilla.mozilla.org/show_bug.cgi?id=1968384 (closed INVALID, the defect being Dovecot's in the interaction between UTF8=ACCEPT and LITERAL+). Any IMAP failure leaving the socket unusable should reproduce the Nextcloud behaviour below.

1. Create an outbox row for a working account: type = 0 (TYPE_OUTGOING), status = 0 (STATUS_RAW), send_at in the past, one recipient.
2. Run the outbox worker once: occ background-job:execute <OutboxWorkerJob id> --force-execute
3. The job takes ~126 s and nextcloud.log shows: Could not send outbox message <id>: Error when communicating with the mail server.
4. The recipient has received the message, but the row in oc_mail_local_messages is unchanged (status = 0, failed = 0).
5. Run the job a second time.

A second, identical email is sent. We confirmed this with two distinct Postfix queue IDs and by the recipient receiving both copies.

In production this ran unattended every ~10 minutes for 5.5 hours and delivered 29 duplicate emails to an external customer (89 duplicates in total across all recipients) before we noticed.

Expected behavior

The message is sent once.

If a step after the SMTP send fails, the resulting state should be persisted so that the send is not repeated. The app already implements this correctly: CopySentMessageHandler catches Horde_Imap_Client_Exception and sets STATUS_IMAP_SENT_MAILBOX_FAIL, and SendHandler skips transmission->sendMessage() for both STATUS_IMAP_SENT_MAILBOX_FAIL and STATUS_PROCESSED.

We verified that guard works as intended: an outbox row pre-set to status = 11 produces zero SMTP sends. The state machine is sound, the problem is purely that the status never reaches the database.

Actual behavior

$client->logout() throws inside the finally block of Send\Chain::process():

$client = $this->clientFactory->getClient($account);
try {
    $result = $handlers->process($account, $localMessage, $client);
} finally {
    $client->logout();                                 // <-- throws here
}

if ($result->getStatus() === LocalMessage::STATUS_PROCESSED) { /* delete */ }
return $this->localMessageMapper->update($result);     // <-- never reached

In PHP an exception thrown inside finally discards the try block's return value and propagates, so localMessageMapper->update($result) is never reached and the row keeps STATUS_RAW. OutboxService::flush() then catches the Throwable, logs a warning and moves on. LocalMessageMapper::findDue() does not filter on status, so the row is selected again on the next run and the entire chain, including the SMTP send is replayed.

Stack trace:

Horde/Imap/Client/Socket.php:4562  read
Horde/Imap/Client/Socket.php:4319  _getLine
Horde/Imap/Client/Socket.php:4243  _sendCmdChunk
Horde/Imap/Client/Socket.php:969   _sendCmd
Horde/Imap/Client/Base.php:891     _logout
lib/Send/Chain.php:56              logout
lib/Service/OutboxService.php:232  process
lib/BackgroundJob/OutboxWorkerJob.php:31  flush

Horde_Imap_Client_Exception: Error when communicating with the mail server. (SERVER_READTIMEOUT)

Suggested fix

Apply the same pattern the codebase already uses for the SMTP transport in MailTransmission::sendMessage() ("Handle silently as this is a resource usage optimization"):

} finally {
    try {
        $client->logout();
    } catch (\Throwable $e) {
        // Logout is cleanup only; it must never discard the send state
    }
}

Related

DraftsService::sendMessage() has the same class of gap: its catch (ClientException|ServiceException) → setFailed(true) guard (comment: "Mark as failed so the message is not moved repeatedly in background") does not catch a raw Horde_Imap_Client_Exception, because that extends Horde_Exception_Wrapped rather than Exception. A draft whose APPEND fails therefore loops on DraftsJob in the same way, silently, since no mail leaves the server.

Mail app version

5.6.4

Nextcloud version

32.0.1

Mailserver or service

Dovecot 2.4.1 (Debian 1:2.4.1+dfsg1-6+deb13u1), Postfix 3.10.4

Operating system

Debian 13 (trixie)

PHP engine version

Other

Nextcloud memory caching

APCu (memcache.local), no distributed cache

Web server

Apache (supported)

Database

MariaDB

Additional info

PHP engine version: 8.4.11 (selected "Other" above because the dropdown stops at 8.3).

default_socket_timeout = 60 on the Nextcloud host, so each failed run hung ~125 s before throwing.

Workaround applied on our side

This mitigates the trigger, not the bug reported here. We scoped the Dovecot setting so it applies only where we actually need it (LMTP, for SMTPUTF8 on PMG quarantine releases) instead of globally:

protocol lmtp { mail_utf8_extensions = yes }

Measured on the same outbox row, before and after:

	before	after
OutboxWorkerJob duration	126 s	1 s
outbox row afterwards	unchanged, replayed on next run	deleted
Dovecot session end	Connection closed (APPEND finished 125.09 secs ago), in=76–85	Logged out, in=443

The in= byte counter is the clearest signal: before the change the client never transferred the message literal at all — Dovecot recorded the APPEND as finished having received only the command line.

The Nextcloud-side defect described above is unchanged by this — it is simply no longer being triggered in our environment. Any other IMAP failure that leaves the socket unusable would hit it again.

[odzhychko]

We did not capture the wire-level IMAP dialog, so we cannot say what Dovecot actually replied.

Hi, you can enable an IMAP/SMTP log what Dovecot actually replies.

[odzhychko]

• From https://bugzilla.mozilla.org/show_bug.cgi?id=1968384
• To https://dovecot.org/mailman3/archives/list/dovecot@dovecot.org/thread/ISDELHRRPVV3PY4SPHYBIVJMTSG5AWAF/
• To dovecot/core@fbcdf6b

This issue was fixed in Dovecot 2.4.2 . So it aligns with @bigthib0 using 2.4.1.

Have to understand the problem, but a first glance the expected behavior "If a step after the SMTP send fails, the resulting state should be persisted so that the send is not repeated" sound right.