[Tickets #15091] Re: ActiveSync permanently skips messages on IMAP error
noreply at bugs.horde.org
noreply at bugs.horde.org
Thu Jan 27 10:47:33 UTC 2022
DO NOT REPLY TO THIS MESSAGE. THIS EMAIL ADDRESS IS NOT MONITORED.
Ticket URL: https://bugs.horde.org/ticket/15091
------------------------------------------------------------------------------
Ticket | 15091
Updated 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