Summary | ActiveSync permanently skips messages on IMAP error |
Queue | Synchronization |
Queue Version | FRAMEWORK_5_2 |
Type | Bug |
State | Resolved |
Priority | 2. Medium |
Owners | mrubinsk (at) horde (dot) org |
Requester | judah (at) maximaweb (dot) dev |
Created | 01/27/2022 (1253 days ago) |
Due | |
Updated | 06/18/2022 (1111 days ago) |
Assigned | 03/24/2022 (1197 days ago) |
Resolved | 06/18/2022 (1111 days ago) |
Github Issue Link | |
Github Pull Request | |
Milestone | |
Patch | No |
commit 6b6c0fd36caf4619baf6c4749bc9b8cf67876846
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date: Sun, 15 May 2022 14:50:05 -0400
[mjr] Don't update state if IMAP server goes away (
Bug #15091).M doc/Horde/ActiveSync/changelog.yml
https://github.com/horde/ActiveSync/commit/6b6c0fd36caf4619baf6c4749bc9b8cf67876846
commit a928f4093695b7964150bf6b6118941fe8c743e7
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date: Sun, 15 May 2022 12:38:25 -0400
[mjr] Don't update state if IMAP server goes away (
Bug #15091).M doc/Horde/ActiveSync/changelog.yml
https://github.com/horde/ActiveSync/commit/a928f4093695b7964150bf6b6118941fe8c743e7
commit e725e70556c60be9cf368421c6516d9b66146f6b
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date: Sun, 15 May 2022 12:27:23 -0400
Attempt to fix
Bug: 15091Don't update state if IMAP server goes away. Mark it as
a temporary error instead.
M lib/Horde/ActiveSync/Imap/Adapter.php
https://github.com/horde/ActiveSync/commit/e725e70556c60be9cf368421c6516d9b66146f6b
State ⇒ Feedback
https://github.com/horde/ActiveSync/commit/a09266d6ce2191260638388e5721f86361402891
Fixes the issue for you before I merge it to our release branch?
State ⇒ Assigned
Assigned to Michael Rubinsky
I will take a look at this soon-ish
Priority ⇒ 2. Medium
Type ⇒ Bug
Summary ⇒ ActiveSync permanently skips messages on IMAP error
Queue ⇒ Synchronization
Milestone ⇒
Patch ⇒ No
State ⇒ Unconfirmed
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