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

* Your Email Address
* Spam protection	Enter the letters below: . ..__ \ /.___\ / \| \|[__) >< [__ >< \|/\\|\| / \[___/ \
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
Attachment
Watch this ticket

Saved Queries