1350442 - Desktop bookmark is not syncing on Android mobile on Aurora 54

Status: VERIFIED FIXED

(Firefox for Android Graveyard :: Android Sync, defect, P1)

Description

[Kanchan Kumari QA]

STR:
1. Launch 54.0a2 (Build ID 	20170324004022)
2. Sign in to Sync with a new or existing Firefox Account on Windows desktop
3. Add a bookmark
4. Trigger sync
5. Sign in to Sync with same Firefox Account on Android mobile
5. Wait for sync to be finish

Expected: Bookmarks from Desktop should appear in Desktop folder on Android mobile

Actual: Desktop bookmark is not on Android mobile on Aurora 54

Note: Bookmarks are syncing properly in following scenarios:
1. From Android to Desktop
2. Desktop to ios
3. Across Desktop platforms (Windows, Linux, Mac)
4. On Nightly channels (Syncing properly from Desktop to Android mobile)

Comment 1

[Lina Butler [:lina]]

Ouch, that's not good. None of the desktop bookmarks sync to Android 54? Grisha, can you think of anything that might have caused this?

Comment 2

[Kanchan Kumari QA]

No none of them are syncing. I performed this test with fresh profile and new Fx account, so I have only a few bookmarks. I am adding bookmark one by one on Desktop, syncing and verifying on Android mobile.  It's syncing perfectly fine from Android mobile to Desktop or on nightly channel. Essentially, I encountered this issue in process of Mobile bookmark folder (on Desktop) testing:)

Comment 3

[Stefan [:StefanG_QA]]

Update: I'm getting the mentioned behavior on Nightly as well. My changes from Android to Desktop are synced correctly, but my 
 latest changes on Desktop to Android are not synced.

Comment 4

[Kanchan Kumari QA]

Changing tracking flag based on comment 3.

Comment 5

[:Grisha Kruglov]

Looking into it. Could you attach android device logs while sync is in progress? Dump of `adb logcat` should be sufficient.

Comment 6

[Kanchan Kumari QA]

Attachment: nexuxlog

Hope this helps.

Comment 7

[Kanchan Kumari QA]

Attachment: Logfile

Comment 8

[:Grisha Kruglov]

What I'm seeing locally:
- desktop changes to bookmarks _are_ downloaded (i see new and changed bookmarks flow through the buffering middleware), but don't seem to be applied. Perhaps something is off with the buffer application logic. If that's the case, we should see the same problem for every collection (excluding history)
- the first log file above seems to indicate that no changes are present on the server. The second log file doesn't cover actual sync unfortunately

I'm going to take a better look at what's going on, something is certainly amiss here.

Comment 9

[:Grisha Kruglov]

Well, this is frustrating. As I suspected, we're simply not calling the right storeDone method on the BookmarksSession - or rather, not overriding the right storeDone method if one looks at it the other way around. The upside is that the patch is very simple.

Comment 10

[:Grisha Kruglov]

Attachment: Bug 1350442 - Remove redundant storeDone from the RepositorySession class

Buffering middleware calls storeDone(timestamp) method at the end of merging, but
bookmarks and form history sessions only overwrote storeDone() method. And so, buffering
middleware would just end up calling their parent's storeDone(timestamp), preventing
pending DB writes from being flushed.

Review commit: https://reviewboard.mozilla.org/r/124572/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/124572/

Comment 11

[:Grisha Kruglov]

This wasn't caught by any of the tests we have for this code, because for the most part they use mock repositories and mock sessions when testing how various bits glue together, and so tests will take a bit more effort to write.

Neither was this caught by my evidently rather insufficient manual testing :-(

At the very least, here's a patch which fixes this issue for me locally and can be easily uplifted to 54.

Comment 12

[:Grisha Kruglov]

A better patch is to kill off storeDone(long end) method entirely and simplify a few things. Sessions often build up buffers which they need to flush on this call, and so passing in a timestamp doesn't make sense in a lot of cases.

Comment 13

[:Grisha Kruglov]

Comment on attachment 8852318 [details]
Bug 1350442 - Remove redundant storeDone from the RepositorySession class

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/124572/diff/1-2/

Comment 14

[u554753]

I can reproduce this with Beta 53b7. With Beta on Desktop as well as Android.

Comment 15

[:Grisha Kruglov]

Can you describe in more details what you're seeing, and confirm that you're seeing it specifically on Firefox for Android 53?
- changing/adding bookmarks on desktop isn't reflected on android?
- changing/adding bookmarks on android isn't reflected on desktop?
- something else..?

Comment 16

[Richard Newman [:rnewman]]

Comment on attachment 8852318 [details]
Bug 1350442 - Remove redundant storeDone from the RepositorySession class

https://reviewboard.mozilla.org/r/124572/#review127828

It seems that a simpler and safer solution is to remove `storeDone()`, ensuring that `storeDone(long)` implements the same behavior, and replace the three uses of the no-argument form in the codebase with uses of `storeDone(long)`, no?

I'm particularly disquieted by the idea of potentially screwing up completion scheduling.

::: commit-message-272ce:4
(Diff revision 2)
> +Bug 1350442 - Remove redundant storeDone from the RepositorySession class r=rnewman
> +
> +Confusion between storeDone() and storeDone(long end) resulted in certain sessions (bookmarks
> +and form history) not overriding the corrent method. As a result, their final "flush the queue"

s/corrent/current

::: mobile/android/services/src/main/java/org/mozilla/gecko/sync/repositories/RepositorySession.java:135
(Diff revision 2)
> -    storeDone(now());
> -  }
> +    // Sessions may override this behaviour if the above assumption is incorrect.
> +    // For example, a session may choose to built up buffers which will need to be flushed in

s/built/build

I'm totally fine with using US or international English throughout a codebase, but ideally not in the same comment, so please use 'behavior' here.

::: mobile/android/services/src/main/java/org/mozilla/gecko/sync/repositories/RepositorySession.java:139
(Diff revision 2)
>      // our end timestamp can just be… now.
> -    storeDone(now());
> -  }
> -
> -  public void storeDone(final long end) {
> +    // Sessions may override this behaviour if the above assumption is incorrect.
> +    // For example, a session may choose to built up buffers which will need to be flushed in
> +    // storeDone, and so it will need to call onStoreComplete with the end timestamp after those
> +    // operations complete.
> +    final long end = System.currentTimeMillis();

Use `now()`.

::: mobile/android/services/src/main/java/org/mozilla/gecko/sync/repositories/android/AndroidBrowserHistoryRepositorySession.java:223
(Diff revision 2)
>              flushNewRecords();
>            } catch (Exception e) {
>              Logger.warn(LOG_TAG, "Error flushing records to database.", e);
>            }
>          }
> -        AndroidBrowserHistoryRepositorySession.super.storeDone(end);
> +        storeDelegate.onStoreCompleted(now());

Same.

::: mobile/android/services/src/main/java/org/mozilla/gecko/sync/repositories/uploaders/BatchingUploader.java:214
(Diff revision 2)
> +    /**
> +     * Must be called on the {@link this#executor }.
> +     * In the current implementation, this call only happens from the PayloadDispatcher.
> +     */
>      /* package-local */ void finished(AtomicLong lastModifiedTimestamp) {
> -        repositorySession.storeDone(lastModifiedTimestamp.get());
> +        sessionStoreDelegate.onStoreCompleted(lastModifiedTimestamp.get());

I have a really hard time thinking this is correct. Consider the definition of `RepositorySession.storeDone(long)`:

```java
138-  public void storeDone(final long end) {
139:    Logger.debug(LOG_TAG, "Scheduling onStoreCompleted for after storing is done: " + end);
140-    Runnable command = new Runnable() {
141-      @Override
142-      public void run() {
143:        storeDelegate.onStoreCompleted(end);
144-      }
145-    };
146-    storeWorkQueue.execute(command);
147-  }
```

`session.storeDone` and `delegate.onStoreCompleted` are *not* interchangeable.

Comment 17

[:Grisha Kruglov]

Comment on attachment 8852318 [details]
Bug 1350442 - Remove redundant storeDone from the RepositorySession class

https://reviewboard.mozilla.org/r/124572/#review127918

::: mobile/android/services/src/main/java/org/mozilla/gecko/sync/repositories/uploaders/BatchingUploader.java:214
(Diff revision 2)
> +    /**
> +     * Must be called on the {@link this#executor }.
> +     * In the current implementation, this call only happens from the PayloadDispatcher.
> +     */
>      /* package-local */ void finished(AtomicLong lastModifiedTimestamp) {
> -        repositorySession.storeDone(lastModifiedTimestamp.get());
> +        sessionStoreDelegate.onStoreCompleted(lastModifiedTimestamp.get());

Well. It's _doing_ the same thing, no? We run runnables on `storeWorkQueue`, which is a single thread executor. This change avoids posting another runnable to the executor, instead performing `onStoreCompleted` at the tail end of the final "store" runnable. This `finished` method is only ever called from the tasks running on the `storeWorkQueue`.

Comment 18

[Richard Newman [:rnewman]]

Comment on attachment 8852318 [details]
Bug 1350442 - Remove redundant storeDone from the RepositorySession class

https://reviewboard.mozilla.org/r/124572/#review127918

> Well. It's _doing_ the same thing, no? We run runnables on `storeWorkQueue`, which is a single thread executor. This change avoids posting another runnable to the executor, instead performing `onStoreCompleted` at the tail end of the final "store" runnable. This `finished` method is only ever called from the tasks running on the `storeWorkQueue`.

The point of the runnable post is to make sure it's the last thing to run. Are you 100% confident that `finished` is always the last runnable to run? A quick skim suggests we call finished <- lastPayloadFailed <- handleRequestError; I haven't checked where our request handling occurs…

Comment 19

[Richard Newman [:rnewman]]

Comment on attachment 8852318 [details]
Bug 1350442 - Remove redundant storeDone from the RepositorySession class

https://reviewboard.mozilla.org/r/124572/#review127918

> The point of the runnable post is to make sure it's the last thing to run. Are you 100% confident that `finished` is always the last runnable to run? A quick skim suggests we call finished <- lastPayloadFailed <- handleRequestError; I haven't checked where our request handling occurs…

Also runnables are really really cheap, particularly if we're already the last item on the same queue. I'm not sure it's worth trying to optimize out a runnable if there's _any_ loss of regularity or risk of miscomprehension, which is why I suggested what I feel is a less risky approach: use the existing adjacent, more explicit code path and remove the problematic one.

Comment 20

[u554753]

(In reply to :Grisha Kruglov from comment #15)
> Can you describe in more details what you're seeing, and confirm that you're
> seeing it specifically on Firefox for Android 53?
> - changing/adding bookmarks on desktop isn't reflected on android?
> - changing/adding bookmarks on android isn't reflected on desktop?
> - something else..?

It syncs from Mobile to Desktop.
It does not sync from Desktop to Mobile.

Apologies for the lack of clarification.

Comment 21

[:Grisha Kruglov]

Comment on attachment 8852318 [details]
Bug 1350442 - Remove redundant storeDone from the RepositorySession class

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/124572/diff/2-3/

Comment 22

[:Grisha Kruglov]

Comment on attachment 8852318 [details]
Bug 1350442 - Remove redundant storeDone from the RepositorySession class

https://reviewboard.mozilla.org/r/124572/#review127828

Rehashing what I've said on IRC: While I don't feel strongly about this (of course!), I do think the current approach is a little cleaner (no need to call `super` implementations of the methods), and embraces the fact that the completion timestamp might be dictated by the session itself (see the commit comment...) - which of course could be achieved either way...

I've switched to calling onStoreCompleted via deferred delegates, which should ensure our scheduling is the same as before. While we don't actually use these timestamps for anything at the moment, they will be used as part of sync ping.

Anyway, let me know if you feel that this change could actually change something about the ordering of things.

> I have a really hard time thinking this is correct. Consider the definition of `RepositorySession.storeDone(long)`:
> 
> ```java
> 138-  public void storeDone(final long end) {
> 139:    Logger.debug(LOG_TAG, "Scheduling onStoreCompleted for after storing is done: " + end);
> 140-    Runnable command = new Runnable() {
> 141-      @Override
> 142-      public void run() {
> 143:        storeDelegate.onStoreCompleted(end);
> 144-      }
> 145-    };
> 146-    storeWorkQueue.execute(command);
> 147-  }
> ```
> 
> `session.storeDone` and `delegate.onStoreCompleted` are *not* interchangeable.

Using deferred delegate now, which posts a runnable, which should achieve the same goal.

Comment 23

[:Grisha Kruglov]

(In reply to Grover Wimberly IV [:Grover-QA] from comment #20)
> It syncs from Mobile to Desktop.
> It does not sync from Desktop to Mobile.

This is a different issue from what the patch above is addressing (since that's a regression in 54, and you're talking about 53). Could you please upload logs while the device is syncing? Output of `adb logcat` should be fine, but in case that's too noisy due to your device, you can filter it: `adb logcat | grep FxAccounts`

Comment 24

[:Grisha Kruglov]

(In reply to :Grisha Kruglov from comment #23)
> Output of `adb logcat` should be
> fine, but in case that's too noisy due to your device, you can filter it:
> `adb logcat | grep FxAccounts`

Actually, a better filter would be: adb logcat | grep "FxAccounts\|GeckoLogger"
What I've posted initially might omit a bunch of stuff.

Comment 25

[Liz Henry (:lizzard) (relman/hg->git project)]

Does this mean bookmarks aren't syncing for 53? That may make this a release blocker. 
Andrei, can your team give this some extra testing for 53 if we still aren't sure?

Comment 26

[u554753]

Attachment: Logcat File

Tried again today and it seems to have synced fine. Attached is the logcat file just in case.

Comment 27

[:Grisha Kruglov]

I expect 54+ to have problems (hence the patch for this bug), but not 53. There were significant changes in 54 and we're seeing those regressions now, but IIRC nothing in 53 changed for sync (batching uploads landed in 51, batching downloads in 52).

Comment 28

[Richard Newman [:rnewman]]

Comment on attachment 8852318 [details]
Bug 1350442 - Remove redundant storeDone from the RepositorySession class

https://reviewboard.mozilla.org/r/124572/#review128778

::: mobile/android/services/src/main/java/org/mozilla/gecko/sync/repositories/android/AndroidBrowserBookmarksRepositorySession.java:979
(Diff revision 3)
>        @Override
>        public void run() {
>          try {
>            finishUp();
>          } finally {
> -          AndroidBrowserBookmarksRepositorySession.super.storeDone();
> +          storeDelegate.deferredStoreDelegate(storeWorkQueue).onStoreCompleted(now());

I'm slightly worried about

```
  public RepositorySessionFetchRecordsDelegate deferredFetchDelegate(ExecutorService newExecutor) {
    if (newExecutor == executor) {
      return this;
    }
    throw new IllegalArgumentException("Can't re-defer this delegate.");
  }

```

— that is, we rely on `storeDelegate.deferredStoreDelegate` always being called with the same `ExecutorService` everywhere. Please convince yourself that this is true.

Comment 29

[:Grisha Kruglov]

Attachment: Bug 1350442 - Use the main storeWorkQueue for failures in the buffering middleware

Review commit: https://reviewboard.mozilla.org/r/126548/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/126548/

Comment 30

[:Grisha Kruglov]

Comment on attachment 8852318 [details]
Bug 1350442 - Remove redundant storeDone from the RepositorySession class

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/124572/diff/3-4/

Comment 31

[:Grisha Kruglov]

Comment on attachment 8852318 [details]
Bug 1350442 - Remove redundant storeDone from the RepositorySession class

https://reviewboard.mozilla.org/r/124572/#review128778

> I'm slightly worried about
> 
> ```
>   public RepositorySessionFetchRecordsDelegate deferredFetchDelegate(ExecutorService newExecutor) {
>     if (newExecutor == executor) {
>       return this;
>     }
>     throw new IllegalArgumentException("Can't re-defer this delegate.");
>   }
> 
> ```
> 
> — that is, we rely on `storeDelegate.deferredStoreDelegate` always being called with the same `ExecutorService` everywhere. Please convince yourself that this is true.

I went through what I think were all of the uses, and all of them seem to use the same `ExecutorService`. Except for the Buffering middleware, which actually created its own queue for use in a very narrow case. See another patch which fixes that.

Comment 32

[Richard Newman [:rnewman]]

Comment on attachment 8854592 [details]
Bug 1350442 - Use the main storeWorkQueue for failures in the buffering middleware

https://reviewboard.mozilla.org/r/126548/#review129092

Comment 33

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/75f204b4d7d3
Use the main storeWorkQueue for failures in the buffering middleware r=rnewman
https://hg.mozilla.org/integration/autoland/rev/45aae5dc504b
Remove redundant storeDone from the RepositorySession class r=rnewman

Comment 34

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/75f204b4d7d3
https://hg.mozilla.org/mozilla-central/rev/45aae5dc504b

Comment 35

[:Grisha Kruglov]

Attachment: desktop-bookmarks-sync-aurora.patch

[Feature/Bug causing the regression]: Bug 1291821, landed in 54.

[User impact if declined]: Changes to bookmarks made on desktop are not reflected in fennec.

[Is this code covered by automated tests?]: Yes

[Has the fix been verified in Nightly?]: Not yet; just landed on m-c at the time of writing.

[Needs manual test from QE? If yes, steps to reproduce]: Yes. Ensure that bookmark sync works both ways, fennec>desktop and desktop>fennec. This includes any changes to individual bookmarks or folders.

[List of other uplifts needed for the feature/fix]: n/a

[Is the change risky?]: Not really.

[Why is the change risky/not risky?]: Simple change; it reduces number of possible code paths, removing a problematic one. Execution ordering or flow of data should not have changed.

[String changes made/needed]: N/A.

Comment 36

[Gerry Chang [:gchang]]

Hi Kanchan,
Can you help verify if this is fixed as expected in a latest nightly?

Comment 37

[Kanchan Kumari QA]

I tested this bug on the latest nightly (Build ID 20170406030206) and found it to be working fine.

Comment 38

[Gerry Chang [:gchang]]

Comment on attachment 8855003 [details] [diff] [review]
desktop-bookmarks-sync-aurora.patch

Fix an issue that desktop bookmark is not syncing on Android mobile and was verified. Aurora54+.

Comment 39

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/48d85433e58b
https://hg.mozilla.org/releases/mozilla-aurora/rev/8e4b96e23d7d

Comment 40

[Kanchan Kumari QA]

Bookmark syncing from Desktop to Mobile is working fine on Aurora 54.0a2 (Build ID 20170407004017)