6.0.0-beta1
7/3/25

[#15091] ActiveSync permanently skips messages on IMAP error
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

History
06/18/2022 10:55:36 PM Michael Rubinsky State ⇒ Resolved
 
05/15/2022 06:50:10 PM Git Commit Comment #6 Reply to this comment
Changes have been made in Git (master):

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
05/15/2022 04:38:42 PM Git Commit Comment #5 Reply to this comment
Changes have been made in Git (FRAMEWORK_5_2):

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
05/15/2022 04:38:41 PM Git Commit Comment #4 Reply to this comment
Changes have been made in Git (FRAMEWORK_5_2):

commit e725e70556c60be9cf368421c6516d9b66146f6b
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date:   Sun, 15 May 2022 12:27:23 -0400

Attempt to fix Bug: 15091

Don'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
03/24/2022 06:23:09 PM Michael Rubinsky Comment #3
State ⇒ Feedback
Reply to this comment
Can you see if:

https://github.com/horde/ActiveSync/commit/a09266d6ce2191260638388e5721f86361402891

Fixes the issue for you before I merge it to our release branch?
01/27/2022 07:37:14 PM Michael Rubinsky Comment #2
State ⇒ Assigned
Assigned to Michael Rubinsky
Reply to this comment
Thank you for the detailed explanation, it really helps.

I will take a look at this soon-ish
01/27/2022 10:43:52 AM judah (at) maximaweb (dot) dev Comment #1
Priority ⇒ 2. Medium
Type ⇒ Bug
Summary ⇒ ActiveSync permanently skips messages on IMAP error
Queue ⇒ Synchronization
Milestone ⇒
Patch ⇒ No
State ⇒ Unconfirmed
Reply to this comment
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

Saved Queries