All users were logged out of Bugzilla on October 13th, 2018

[email] synchronization resulting from "bad sync key" will never synchronize messages known to the database at the time of "bad sync key"; easily triggered by changing "Synchronize" per-account setting

VERIFIED FIXED

Status

VERIFIED FIXED
6 years ago
5 years ago

People

(Reporter: nhirata, Assigned: squib)

Tracking

({regression})

unspecified
ARM
Gonk (Firefox OS)
regression

Firefox Tracking Flags

(blocking-b2g:tef+, b2g18+ fixed, b2g18-v1.0.0 fixed)

Details

Attachments

(2 attachments)

## Environment :
Gecko  http://hg.mozilla.org/releases/mozilla-b2g18/rev/0e43266ca3c6
Gaia   1890022f3ca36108621a832f31ac5df8bf89a22e
BuildID 20130122070203
Version 18.0
Unagi

## Repro :
1. setup an active sync account w/ email
2. go to account settings
3. select the account
4. change the sync time settings to anything but all

## Expected :
1. it will show some email

## Actual :
1. nothing shows

## Note: 
bug 805230 removes 3/6 months...
I had used portuguese...
I really need to follow https://wiki.mozilla.org/Gaia/Email/RequiredBugInfo...
will follow up with logcat; creating this email as a place holder...
Also, how old is the newest message in the Inbox in the test account?
Created attachment 706519 [details]
logcat

at 11:52, I hit "goto mail" for the email setup to get the email and did see all my messages.

I went and check each line, and didn't see anything in the email for any of the lines... some of which was expected because I had 2 for 24, 5 for the 18th.  However... for the 1 month view it should have shown something but it didn't even after I refreshed.  I sent myself an email and I saw 1 email for the month view.  I set the setting to automatic and the email disappeared.  Does the secret debug mode work still?  I don't see anything helpful in the log other than that I OOMed...
Your logcat includes repeated notifications (4 times) of
  WAR: ActiveSync had a bad sync key
and there were a few
  LOG: Sync completed with empty response

This looks a lot like: Bug 825538 - [email/activesync] Need to allocate unique device ID's for multi-device access to ActiveSync

Is it possible someone else was testing the e-mail app against the save ActiveSync account when you were testing this?  Maybe you were using 2 devices?
I don't think at the same time as I was testing on this phone.
Having said that, I do tend to flash and resetup the account on this phone.

Would browsing the account in a web browser cause the same issue?
(In reply to Naoki Hirata :nhirata from comment #4)
> Would browsing the account in a web browser cause the same issue?

No, not unless you were using the gaia e-mail app in the browser.  (The issue is that the ActiveSync server can't tell instances of the gaia e-mail app apart for the same user account.)

My skim of the log was way too fast this afternoon, apologies.  All of the bad sync keys were most likely a result of you changing the settings.  (The "CONFIG CURRENTLY" stuff is global settings, but it does tell us when you brought up the settings UI.)

I am 100% able to reproduce what you are seeing here.

The general phenomenon, as the log alludes to, seems to be that when we encounter the bad sync key, we re-create the folder and successfully synchronize our messages, but they effectively go into a black hole instead of where they are supposed to go.  We do manage to persist the sync-key correctly, though, so you will only get new messages received after that synchronization.  Additionally, we will probably experience _blockInfo lookup failures whenever a deletion occurs during sync.  I'll take a look at the activesync unit tests now to have a better idea of what's going on.

Here's the filtered log:
===
01-25 11:52:05.751: I/GeckoDump(933): LOG: We want a filter of all messages
01-25 11:52:21.376: I/GeckoDump(933): LOG: Sync completed: added 41, changed 0, deleted 0
01-25 11:52:21.446: I/GeckoDump(933): LOG: Sync Completed! 41 messages synced
01-25 11:52:26.511: I/GeckoDump(933): LOG:   CONFIG CURRENTLY: {"debugLogging":false,"syncCheckIntervalEnum":"manual"}
01-25 11:52:33.528: I/GeckoDump(933): WAR: ActiveSync had a bad sync key
01-25 11:52:35.970: I/GeckoDump(933): LOG: Sync completed: added 2, changed 0, deleted 0
01-25 11:52:35.970: I/GeckoDump(933): LOG: Sync Completed! 0 messages synced
01-25 11:53:15.419: I/GeckoDump(933): LOG: Sync completed with empty response
01-25 11:53:18.602: I/GeckoDump(933): LOG:   CONFIG CURRENTLY: {"debugLogging":false,"syncCheckIntervalEnum":"manual"}
01-25 11:53:26.980: I/GeckoDump(933): WAR: ActiveSync had a bad sync key
01-25 11:53:29.212: I/GeckoDump(933): LOG: Sync completed: added 2, changed 0, deleted 0
01-25 11:53:29.212: I/GeckoDump(933): LOG: Sync Completed! 0 messages synced
01-25 11:53:40.103: I/GeckoDump(933): LOG:   CONFIG CURRENTLY: {"debugLogging":false,"syncCheckIntervalEnum":"manual"}
01-25 11:53:45.608: I/GeckoDump(933): WAR: ActiveSync had a bad sync key
01-25 11:53:49.522: I/GeckoDump(933): LOG: Sync completed: added 9, changed 0, deleted 0
01-25 11:53:49.532: I/GeckoDump(933): LOG: Sync Completed! 0 messages synced
01-25 11:53:52.975: I/GeckoDump(933): LOG: Sync completed with empty response
01-25 11:54:44.976: I/GeckoDump(933): LOG: Sync completed: added 1, changed 0, deleted 0
01-25 11:54:54.005: I/GeckoDump(933): LOG:   CONFIG CURRENTLY: {"debugLogging":false,"syncCheckIntervalEnum":"manual"}
01-25 11:55:00.271: I/GeckoDump(933): WAR: ActiveSync had a bad sync key
===
(Assignee)

Comment 6

6 years ago
Gimme gimme. I think I know what's going on here, although I will be extremely interested to see when I broke this, since I distinctly recall manually testing this.
Assignee: nobody → squibblyflabbetydoo
Status: NEW → ASSIGNED
I think part of the issue is that the test_activesync_recreate unit test is still orange right now; you had a pull request to fix it up at https://github.com/mozilla-b2g/gaia-email-libs-and-more/pull/114 but I took issue with your fix and then I think the ball got dropped.

I was just looking at test_activesync_general, and although it does change the sync range in a test, it doesn't actually try and refresh/resync after changing the sync range, so that test is not testing this case either.
Actually, scratch the activesync_recreate test; although it's a similar code-path, it's not the same.  We need to modify test_activesync_general or something else to exercise this code path.
(Assignee)

Comment 9

6 years ago
Ok, the breakage is because we now check if we already know about a header with that server id before adding it. Since we weren't clearing out the server id mapping from the folderMeta when recreating the folder, this caused some breakage. All in all, pretty easy to fix. I'm working on tests now.
(Assignee)

Updated

6 years ago
blocking-b2g: --- → tef?
tracking-b2g18: --- → ?
Keywords: regression
(Assignee)

Comment 11

6 years ago
I merged the GELAM part: https://github.com/mozilla-b2g/gaia-email-libs-and-more/pull/116

Just waiting to see if this gets marked blocking so I can merge into Gaia proper...
gaia/master is open, so you can land on that at least
(Assignee)

Comment 13

6 years ago
(In reply to Andrew Sutherland (:asuth) from comment #12)
> gaia/master is open, so you can land on that at least

Open as in "doesn't need approval to land"?
(In reply to Jim Porter (:squib) from comment #13)
> (In reply to Andrew Sutherland (:asuth) from comment #12)
> > gaia/master is open, so you can land on that at least
> 
> Open as in "doesn't need approval to land"?

Right, just r+

https://wiki.mozilla.org/Release_Management/B2G_Landing could be more clear, but the pictorial explanation is more explicit that landing requirements are just r+.  (I'm also drawing on other comments by Alex Keybl, like "We're going to be repurposing approval-gaia-master into approval-gaia-v1train (approval for tracking-b2g18+ bugs) since master is now v2 and requires no approval.")
Andrew, we need to understand the user impact
Flags: needinfo?(bugmail)
(In reply to David Scravaglieri [:scravag] from comment #15)
> Andrew, we need to understand the user impact

If a 'bad sync key' is received when synchronizing a folder, we do not clear out our previous state entirely, so any messages that we are told about that the database had previously known about will not be synchronized.

The settings page for each account provides a "Synchronize" setting with values: "Automatic" (default based on message estimates in the folder), 1 day, 3 days, 1 week, 2 weeks, 1 month, all messages.

Bad sync keys can occur because the server has deleted our folder state, or because the user changed the "synchronize" setting.

The general result is that synchronization will appear to be missing all the messages that we knew about from the previous synchronization.

This is a simple fix with extremely low risk and (now) has unit tests.
Flags: needinfo?(bugmail)
Triage call is that this doesn't seem like something we'd hold the release for.  Is it possible to request uplift for the patch but then if it bounces we don't worry about it?

Also, we discussed this during triage without any gaia input so I should probably not be the one making this call :)
blocking-b2g: tef? → -
(Assignee)

Comment 18

6 years ago
Checked into gaia/master: https://github.com/mozilla-b2g/gaia/pull/7828

As for uplifting this, I think this is pretty important, since it effectively means that users can't change the synchronization range for their ActiveSync accounts. At the very least, if we don't accept this patch, we should disable the ability for people to change the sync range and break their folders.
(Assignee)

Updated

6 years ago
Status: ASSIGNED → RESOLVED
Last Resolved: 6 years ago
Resolution: --- → FIXED
Summary: [email] Activesync synchronization for everything but all do not show any emails. → [email] synchronization resulting from "bad sync key" will never synchronize messages known to the database at the time of "bad sync key"; easily triggered by changing "Synchronize" per-account setting
Created attachment 708220 [details] [review]
https://github.com/mozilla-b2g/gaia/pull/7828

NOTE: If blocking-basecamp+ is set, just land it for now.

[Approval Request Comment]
See https://bugzilla.mozilla.org/show_bug.cgi?id=834448#c16
Attachment #708220 - Flags: review+
Attachment #708220 - Flags: approval-gaia-v1?(21)
As per comment 18, we'd rather take this fix than do the disabling of sync range - please uplift to branches asap.
blocking-b2g: - → tef+
status-b2g18: --- → affected
status-b2g18-v1.0.0: --- → affected
tracking-b2g18: ? → +
Comment on attachment 708220 [details] [review]
https://github.com/mozilla-b2g/gaia/pull/7828

clearing approval request now that this is a blocker and does not require approval to uplift.
Attachment #708220 - Flags: approval-gaia-v1?(21)
v1-train: 841343a4445cad89ef7c9eefa2bded008854e713
v1.0.0: fa9e1b55dc1048d595617d14d41b7d57f696132b
status-b2g18: affected → fixed
status-b2g18-v1.0.0: affected → fixed

Comment 23

6 years ago
Verified fixed on:

Gecko: http://hg.mozilla.org/releases/mozilla-b2g18_v1_0_1/rev/98354c0298ab
Gaia: edaca00b1eb7534120b6255db5d5200fb1d86d65   
build: 20130219070200
kernel date: Dec 5
Status: RESOLVED → VERIFIED
Attachment mime type: text/plain → text/x-github-pull-request
You need to log in before you can comment on or make changes to this bug.