834448 - [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

Status: VERIFIED FIXED

(Firefox OS Graveyard :: Gaia::E-Mail, defect)

Description

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

## 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...

Comment 1

[Andrew Sutherland [:asuth] (he/him)]

Also, how old is the newest message in the Inbox in the test account?

Comment 2

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

Attachment: 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...

Comment 3

[Andrew Sutherland [:asuth] (he/him)]

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?

Comment 4

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

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?

Comment 5

[Andrew Sutherland [:asuth] (he/him)]

(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
===

Comment 6

[Jim Porter (:squib)]

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.

Comment 7

[Andrew Sutherland [:asuth] (he/him)]

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.

Comment 8

[Andrew Sutherland [:asuth] (he/him)]

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.

Comment 9

[Jim Porter (:squib)]

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.

Comment 10

[Jim Porter (:squib)]

PR up for review: https://github.com/mozilla-b2g/gaia-email-libs-and-more/pull/116

Comment 11

[Jim Porter (:squib)]

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...

Comment 12

[Andrew Sutherland [:asuth] (he/him)]

gaia/master is open, so you can land on that at least

Comment 13

[Jim Porter (:squib)]

(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"?

Comment 14

[Andrew Sutherland [:asuth] (he/him)]

(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.")

Comment 15

[David Scravaglieri [:scravag]]

Andrew, we need to understand the user impact

Comment 16

[Andrew Sutherland [:asuth] (he/him)]

(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.

Comment 17

[Andrew Overholt [:overholt]]

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 :)

Comment 18

[Jim Porter (:squib)]

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.

Comment 19

[Andrew Sutherland [:asuth] (he/him)]

Attachment: 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

Comment 20

[Lukas Blakk [:lsblakk] use ?needinfo]

As per comment 18, we'd rather take this fix than do the disabling of sync range - please uplift to branches asap.

Comment 21

[Lukas Blakk [:lsblakk] use ?needinfo]

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.

Comment 22

[John Ford [:jhford] CET/CEST Berlin Time]

v1-train: 841343a4445cad89ef7c9eefa2bded008854e713
v1.0.0: fa9e1b55dc1048d595617d14d41b7d57f696132b

Comment 23

[mlevin]

Verified fixed on:

Gecko: http://hg.mozilla.org/releases/mozilla-b2g18_v1_0_1/rev/98354c0298ab
Gaia: edaca00b1eb7534120b6255db5d5200fb1d86d65   
build: 20130219070200
kernel date: Dec 5