[Tickets #15091] ActiveSync permanently skips messages on IMAP error

noreply at bugs.horde.org noreply at bugs.horde.org
Thu Jan 27 10:43:52 UTC 2022


DO NOT REPLY TO THIS MESSAGE. THIS EMAIL ADDRESS IS NOT MONITORED.

Ticket URL: https://bugs.horde.org/ticket/15091
------------------------------------------------------------------------------
  Ticket             | 15091
  Created By         | judah at maximaweb.dev
  Summary            | ActiveSync permanently skips messages on IMAP error
  Queue              | Synchronization
  Version            | FRAMEWORK_5_2
  Type               | Bug
  State              | Unconfirmed
  Priority           | 2. Medium
  Milestone          |
  Patch              |
  Owners             |
------------------------------------------------------------------------------


judah at maximaweb.dev (2022-01-27 10:43) wrote:

When an ongoing IMAP connection is lost in the middle of a sync, horde  
skips the remaining messages without retrying the connection.  However  
internally it considers those messages to have been synced correctly  
and doesn't ever attempt to sync them again, leading to permanent  
partial or incomplete folder contents in the email client.

Background:
We have to reload Dovecot semi-regularly (at least hourly) to update  
its internal TLS configuration as certificates are added or renewed.   
When Dovecot is reloaded, it terminates all its child processes  
including open IMAP connections.  That means that occasionally horde  
gets its open IMAP connection killed from under it in the middle of a  
sync.  Yes, this is dumb on Dovecot's end, but there doesn't seem to  
be any way to avoid it.

Horde considers that an "Unknown backend error" and skips that message  
and all subsequent messages in the sync.  However it still updates the  
state of that message to consider it synced.

This issue especially manifests itself on the initial sync of large  
email accounts as those syncs can take  hours in some cases.  That's  
also the worst time for it to occur as it means the sync can end up  
permanently skipping thousands of emails.

Here's some log extracts that hopefully illustrate the problem.

Horde starts syncing the inbox:
[2820904][2022-01-27T01:24:08+11:00] >>>: Creating new folder uuid for  
INBOX: F638a9c0b
[2820904][2022-01-27T01:24:11+11:00] >>>: STATE: Found 8552 message  
changes in F638a9c0b.

-- 6070 emails are synced successfully --

Then Dovecot is reloaded and terminates its imap processes:
Jan 27 01:50:21 server dovecot[2148063]: master: Warning: SIGHUP  
received - reloading configuration
Jan 27 01:50:35 server dovecot[2148063]: master: Warning: Sent SIGTERM  
to 1 stats processes
Jan 27 01:50:35 server dovecot[2148063]: master: Warning: Sent SIGTERM  
to 1 imap processes
Jan 27 01:50:35 server dovecot[2148063]: master: Warning: Sent SIGTERM  
to 1 imap-login processes
Jan 27 01:50:35 server dovecot[2148063]: master: Warning: Sent SIGTERM  
to 1 config processes
Jan 27 01:50:35 server dovecot[2148063]: master: Warning: Sent SIGTERM  
to 1 auth processes
Jan 27 01:50:35 server dovecot[2148063]: master: Warning: Processes  
aren't dying after reload, sent SIGTERM to 5 processes.
Jan 27 01:50:35 server dovecot[2827587]: imap: Warning: Killed with  
signal 15 (by pid=2148063 uid=0 code=kill)
Jan 27 01:50:35 server dovecot[2827587]:  
imap(<email-address>)<2829269>: Server shutting down. in=141913  
out=807919706 deleted=0 expunged=0 trashed=0 hdr_count=438  
hdr_bytes=3459189 body_count=2183 body_bytes=803418681

The Horde sync is interrupted on message 6071:
[2820226][2022-01-27T01:52:04+11:00] >>>:  
Horde_Core_ActiveSync_Driver::getMessage(INBOX, 6071)
[2820226][2022-01-27T01:52:05+11:00] ERR: Unable to fetch message:  
IMAP Server closed the connection.
[2820226][2022-01-27T01:52:05+11:00] ERR: IMAP Server closed the connection.
[2820226][2022-01-27T01:52:05+11:00] ERR: Unknown backend error  
skipping message: IMAP Server closed the connection.
[2820226][2022-01-27T01:52:05+11:00] >>>: STATE: Updating state during change
[2820226][2022-01-27T01:52:05+11:00] >>>: Peak memory usage after  
message: 188751872
[2820226][2022-01-27T01:52:05+11:00] >>>:  
Horde_Core_ActiveSync_Driver::getMessage(INBOX, 6072)
[2820226][2022-01-27T01:52:05+11:00] ERR: Unable to fetch message:  
IMAP error reported by server.
[2820226][2022-01-27T01:52:05+11:00] ERR: IMAP error reported by server.
[2820226][2022-01-27T01:52:05+11:00] ERR: Unknown backend error  
skipping message: IMAP error reported by server.
[2820226][2022-01-27T01:52:05+11:00] >>>: STATE: Updating state during change
[2820226][2022-01-27T01:52:05+11:00] >>>: Peak memory usage after  
message: 188751872

Notice only the first message skipped reports the actual error "IMAP  
Server closed the connection".  All subsequent messages simply report  
"IMAP error reported by server".

Over the course of the next second, without attempting to retry the  
connection, the Horde ActiveSync Driver skips over the remaining 2500+  
messages:
[2820226][2022-01-27T01:52:06+11:00] >>>:  
Horde_Core_ActiveSync_Driver::getMessage(INBOX, 8595)
[2820226][2022-01-27T01:52:06+11:00] ERR: Unable to fetch message:  
IMAP error reported by server.
[2820226][2022-01-27T01:52:06+11:00] ERR: IMAP error reported by server.
[2820226][2022-01-27T01:52:06+11:00] ERR: Unknown backend error  
skipping message: IMAP error reported by server.
[2820226][2022-01-27T01:52:06+11:00] >>>: STATE: Updating state during change
[2820226][2022-01-27T01:52:06+11:00] >>>: Peak memory usage after  
message: 188751872
[2820226][2022-01-27T01:52:06+11:00] >>>:  
Horde_Core_ActiveSync_Driver::getMessage(INBOX, 8596)
[2820226][2022-01-27T01:52:06+11:00] ERR: Unable to fetch message:  
IMAP error reported by server.
[2820226][2022-01-27T01:52:06+11:00] ERR: IMAP error reported by server.
[2820226][2022-01-27T01:52:06+11:00] ERR: Unknown backend error  
skipping message: IMAP error reported by server.
[2820226][2022-01-27T01:52:06+11:00] >>>: STATE: Updating state during change
[2820226][2022-01-27T01:52:06+11:00] >>>: Peak memory usage after  
message: 188751872

However it seems it is incorrectly updating the STATE of each message  
during this time.  Hence when a new sync starts just a few seconds  
later, Horde considers the sync of that folder to have been completed  
successfully and reports:
[2820904][2022-01-27T01:53:18+11:00] >>>: STATE: Found 0 message  
changes in F638a9c0b.

I hope that's not too much detail!  While having Horde retry the IMAP  
connection would be nice, I think the real problem is that skipping  
messages caused by IMAP errors incorrectly updates the state of those  
messages as synced when actually they need to be retried.

Please don't hesitate to contact me if you need more information.

Many thanks,
Judah





More information about the bugs mailing list