Closed Bug 1941655 Opened 1 year ago Closed 1 year ago

Sync of bookmarks fails on Fenix: Store error: Error executing SQL: update: item without parent (#0)

Categories

(Firefox for Android :: Accounts and Sync, defect, P2)

Product:
Firefox for Android
Component:
Accounts and Sync
Version:
Firefox 136
Platform:
All
Android
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
136 Branch
Tracking Flags:
Tracking Status
firefox134 --- unaffected
firefox135 + fixed
firefox136 + fixed

People

(Reporter: artella.coding, Assigned: markh)

References

(Regression)

Details

(Keywords: regression)

Attachments

(7 files)

log.txt
7.80 KB, text/plain
Details
[mozilla/application-services] Increase bookmark sync log levels to try and narrow down bug 1941655. (#6559)
57 bytes, text/x-github-pull-request
Details | Review
log_on_20250115.txt
12.19 KB, text/plain
Details
FirefoxNightlyLog
24.20 KB, text/plain
Details
[mozilla/application-services] Bug 1941655 - relax places DB constraints to what they were before bu… (#6564)
57 bytes, text/x-github-pull-request
Details | Review
[mozilla/application-services] Bug 1941655 - relax places DB constraints to what they were before bu… (backport #6564) (#6569)
57 bytes, text/x-github-pull-request
Details | Review
Bug 1941655 - Bump Application Services to 135.0.1.
48 bytes, text/x-phabricator-request
phab-bot
: approval-mozilla-release+
Details | Review

Steps to reproduce:

3 dots on right -> settings -> account -> "Sync now"

on Android Firefox Nightly 136.0a1 (Build #2016067423)

Actual results:

Sync completes but bookmarks dont update

Expected results:

Bookmarks should update to reflect changes on desktop.

***** DEBUG INFO *****

https://firefox-source-docs.mozilla.org/mobile/android/fenix/Logging-Crash-Information.html

adb logcat returns the following lines :

01-14 19:53:04.715 I/sync15::client::sync_multiple( 7717): Syncing bookmarks engine!
01-14 19:53:04.716 I/sync15::client::sync( 7717): Syncing collection bookmarks
01-14 19:53:04.719 I/sync15::client::sync( 7717): skipping incoming for bookmarks - not needed.
01-14 19:53:05.413 W/sync15::client::sync_multiple( 7717): Sync of bookmarks failed! StoreError(Error executing SQL: update: item without parent (#0)
01-14 19:53:05.474 I/sync_manager::manager( 7717): engine "bookmarks" status: Err(StoreError(Error executing SQL: update: item without parent (#0)
01-14 19:53:05.497 E/SyncWorker( 7717): Failed to sync bookmarks, reason: Store error: Error executing SQL: update: item without parent (#0)
01-14 19:53:05.512 I/libglean_ffi( 7717): glean_core::ping: Collecting bookmarks-sync
01-14 19:53:05.518 I/libglean_ffi( 7717): glean_core::metrics::ping: The ping 'bookmarks-sync' was submitted and will be sent as soon as possible
01-14 19:53:06.234 I/libglean_ffi( 7717): glean_core::upload: New upload task with id 3f337f55-e450-43a7-8429-b262f5bc9dc0 (path: /submit/org-mozilla-fenix/bookmarks-sync/1/3f337f55-e450-43a7-8429-b262f5bc9dc0)
01-14 19:54:30.080 I/sync_manager::manager( 7717): breadcrumb: Checking engines requested (Some { engines: ["history", "bookmarks", "passwords", "tabs", "creditcards"] }) vs local engines (["passwords", "tabs", "bookmarks", "addresses", "creditcards", "history"])
01-14 19:54:31.033 I/sync15::client::sync_multiple( 7717): Syncing bookmarks engine!
01-14 19:54:31.034 I/sync15::client::sync( 7717): Syncing collection bookmarks
01-14 19:54:31.036 I/sync15::client::sync( 7717): skipping incoming for bookmarks - not needed.
01-14 19:54:31.741 W/sync15::client::sync_multiple( 7717): Sync of bookmarks failed! StoreError(Error executing SQL: update: item without parent (#0)
01-14 19:54:31.802 I/sync_manager::manager( 7717): engine "bookmarks" status: Err(StoreError(Error executing SQL: update: item without parent (#0)
01-14 19:54:31.825 E/SyncWorker( 7717): Failed to sync bookmarks, reason: Store error: Error executing SQL: update: item without parent (#0)
01-14 19:54:31.840 I/libglean_ffi( 7717): glean_core::ping: Collecting bookmarks-sync
01-14 19:54:31.846 I/libglean_ffi( 7717): glean_core::metrics::ping: The ping 'bookmarks-sync' was submitted and will be sent as soon as possible
01-14 19:54:32.565 I/libglean_ffi( 7717): glean_core::upload: New upload task with id f1c2bca3-2fa6-4754-a244-f67d150a25cf (path: /submit/org-mozilla-fenix/bookmarks-sync/1/f1c2bca3-2fa6-4754-a244-f67d150a25cf)
01-14 19:54:33.877 I/sync_manager::manager( 7717): breadcrumb: Checking engines requested (Some { engines: ["history", "bookmarks", "passwords", "tabs", "creditcards"] }) vs local engines (["passwords", "tabs", "bookmarks", "addresses", "creditcards", "history"])
01-14 19:54:34.824 I/sync15::client::sync_multiple( 7717): Syncing bookmarks engine!

Severity: -- → S2
Status: UNCONFIRMED → NEW
Ever confirmed: true
Keywords: regression
Priority: -- → P2
Regressed by: 1935797
Summary: Sync of bookmarks fails on Firefox Android Nightly → Sync of bookmarks fails on Fenix: Store error: Error executing SQL: update: item without parent (#0)

Hi sorry in the report above I forgot to point out the line :

"01-14 19:54:31.825 E/SyncWorker( 7717): Failed to sync bookmarks, reason: Store error: Error executing SQL: update: item without parent (#0)"

Sorry again just noticed Mark already added this line to title. Thank you Mark.

:lina, since you are the author of the regressor, bug 1935797, could you take a look?

For more information, please visit BugBot documentation.

Flags: needinfo?(lina)
Flags: needinfo?(markh)

The bug is marked as tracked for firefox135 (beta) and tracked for firefox136 (nightly). However, the bug still isn't assigned.

:boek, could you please find an assignee for this tracked bug? Given that it is a regression and we know the cause, we could also simply backout the regressor. If you disagree with the tracking decision, please talk with the release managers.

For more information, please visit BugBot documentation.

Flags: needinfo?(jboek)
Flags: needinfo?(lina)

Thanks for the report - it looks like this logcat output might be filtered - maybe for "bookmark"? Eg, there should almost certainly be a line immediately under skipping incoming for bookmarks - not needed. with Applying changes but I don't see it.

If it is filtered, would it be possible to upload a slightly less filtered version? Ideally everything from the same process, which I think is the 7717 in your logs. This might help me better understand exactly where this is failing.

(It probably will not, but it can't hurt! What's interesting is that the log is clear there's nothing coming in from the server, so somehow this error is being generated as we are preparing to upload existing local items to the server, which I'm struggling to make sense of)

Flags: needinfo?(markh) → needinfo?(artella.coding)
Attached file log.txt —
Hi thanks for looking into this. Yes I was filtering by bookmark. I have attached a more complete log . Let me know if you need more of the logs.

Thanks! Logs from a little earlier would be great - eg, it should include the line 01-14 19:53:04.715 I/sync15::client::sync_multiple( 7717): Syncing bookmarks engine! and ending somewhere around Failed to sync bookmarks, reason: Store error: Error executing SQL: update: item without parent (#0) would be perfect.

(to be clear, not those exact lines - ie, the timestamps and process-ids will be different!)

Actually, it's fine to not upload better logs today, because in a few days Nightly should log even more for bookmark syncing and it's those new logs that would be most helpful!

Authored by https://github.com/mhammond
https://github.com/mozilla/application-services/commit/d7049d23dcd1c193f0bbe51d7cbcebb20963c197
[main] Increase bookmark sync log levels to try and narrow down bug 1941655.

Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → FIXED

oops...

Status: RESOLVED → REOPENED
Keywords: leave-open
Resolution: FIXED → ---
Attached file log_on_20250115.txt —
Yesterday after your message above I reran and got the attached logs.

However today a new update of Android Nightly arrived and when I try to sync nothing happens (in yesterday's version sync actually did something). Also the logs dont show anything useful.

My new version is 136.0a1 (Build #2016067807), hg-234c9429e537+.

I tried restarting my phone, doing a Force Stop on Firefox Nightly etc, but it didnt help. Will try again later today.

Thanks

Flags: needinfo?(artella.coding)
Attached file FirefoxNightlyLog —
Hi I just tried syncing and it worked this time round [for Android Nightly 136.0a1 (Build #2016067807), hg-234c9429e537+]. I have attached the new logs. Note I also have : a) Firefox Release [134.0.1 (Build #2016067655), hg-497a35d032e4+] and bookmarks sync works fine. b) Firefox Beta [135.0b4 (Build #2016067639), hg-71e39ff19c29+] and bookmarks sync does not work on this either. This is consistent with the information provided above by others.

This is a reminder regarding comment #4!

The bug is marked as tracked for firefox136 (nightly). We have limited time to fix this, the soft freeze is in 9 days. However, the bug still isn't assigned.

My best guess is that this is caused by this "ON CONFLICT" clause - note the lack of "parent" in that clause.

I can reproduce something similar to this with these STR:

  • Run our places-utils example to setup a DB with bookmarks via sync.
  • Use a sqlite editor and locate a folder which has bookmarks.
  • Delete the parent item (thus making the bookmarks tree invalid as items will reference a non-existing parent)
  • Run places-utils again to sync.

When doing this I get an error from the above-linked SQL about a conflict on guid - however, note the above clause is only for id. So if we modify the SQL such that guid is also handled (ie, copy the ON CONFLICT clause changing id to guid in the copy), and then we can get the same error we see.

Matching the error exactly probably requires things to be setup so it really is the id rather than the guid which conflicts - which probably requires more time to understand exactly the circumstances where this conflict is expected.

Naively, I tried changing the ON CONFLICT clause to include parent and set it to the root ID as described in the comments - this does allow the sync to complete without error, but causes tests to fail as the final tree is not what's expected - ie, the omission of parent appears intentional and that in this scenario, dogear has created a valid tree. IOW, it does appear that the condition here can be seen for real and does not imply the final bookmarks tree will be invalid.

So I think we should:

  • Change the trigger to exactly match what was there before, get that landed.
  • Spend more time better trying to understand this scenario and get test cases landed with the stricter rules.
Flags: needinfo?(jboek)

:markh : thanks a lot for looking in such depth at the issue. On my side I am not in a rush to have this fixed and would prefer to wait for you to finish investigating. Thanks

Hi I just tested with version 136.0a1 (Build #2016069543), hg-0da4e2f4d975+, and I am getting a new error. Not sure if it is related to bug above :

01-26 14:00:14.511 I/sync_manager::manager(26492): breadcrumb: SyncManager::sync started
01-26 14:00:14.542 I/sync_manager::manager(26492): breadcrumb: Checking engines requested (Some { engines: ["history", "bookmarks", "passwords", "tabs", "creditcards"] }) vs local engines (["passwords", "tabs", "bookmarks", "addresses", "creditcards", "history"])
01-26 14:00:14.542 I/sync_manager::manager(26492): No backoff in effect (or we decided to ignore it), starting sync
01-26 14:00:14.547 E/uniffi_core::ffi::rustcalls(26492): Caught a panic calling rust code: "not implemented: This engine does not support local encryption"
01-26 14:00:14.548 E/WM-WorkerWrapper(26492): Work [ id=787b732e-b840-4636-896e-90ea9629e344, tags={ mozilla.components.service.fxa.sync.WorkManagerSyncWorker,Common,Immediate } ] failed because it threw an exception/error
01-26 14:00:14.548 E/WM-WorkerWrapper(26492): mozilla.appservices.syncmanager.InternalException: not implemented: This engine does not support local encryption
01-26 14:00:14.548 E/WM-WorkerWrapper(26492): at mozilla.appservices.syncmanager.SyncmanagerKt.uniffiCheckCallStatus(syncmanager.kt:40)
01-26 14:00:14.548 E/WM-WorkerWrapper(26492): at mozilla.appservices.syncmanager.SyncmanagerKt.access$uniffiCheckCallStatus(syncmanager.kt:1)
01-26 14:00:14.548 E/WM-WorkerWrapper(26492): at mozilla.appservices.syncmanager.SyncManager.sync(syncmanager.kt:71)
01-26 14:00:14.548 E/WM-WorkerWrapper(26492): at mozilla.components.service.fxa.sync.WorkManagerSyncWorker.access$doSync(WorkManagerSyncManager.kt:970)
01-26 14:00:14.548 E/WM-WorkerWrapper(26492): at mozilla.components.service.fxa.sync.WorkManagerSyncWorker$doWork$2.invokeSuspend(WorkManagerSyncManager.kt:332)
01-26 14:00:14.548 E/WM-WorkerWrapper(26492): at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:9)
01-26 14:00:14.548 E/WM-WorkerWrapper(26492): at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:111)
01-26 14:00:14.548 E/WM-WorkerWrapper(26492): at kotlinx.coroutines.internal.LimitedDispatcher$Worker.run(LimitedDispatcher.kt:4)
01-26 14:00:14.548 E/WM-WorkerWrapper(26492): at kotlinx.coroutines.scheduling.TaskImpl.run(Tasks.kt:3)
01-26 14:00:14.548 E/WM-WorkerWrapper(26492): at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:96)

Actually I think it might be due to another commit e.g.

https://github.com/mozilla/application-services/commit/ccf4467f548870de91655cb38a666dde15b2632e

I will post a seperate bug. Thanks

This is a reminder regarding comment #4!

The bug is marked as tracked for firefox136 (nightly). We have limited time to fix this, the soft freeze is in 3 days. However, the bug still isn't assigned.

Assignee: nobody → markh

Telemetry shows this was fixed by https://github.com/mozilla/application-services/pull/6564

Status: REOPENED → RESOLVED
Closed: 1 year ago → 1 year ago
Resolution: --- → FIXED
status-firefox136: affected → fixed
Target Milestone: --- → 136 Branch
Attachment #9461969 - Flags: approval-mozilla-release?
Attachment #9461969 - Flags: approval-mozilla-release? → approval-mozilla-release+

Thanks everyone for helping getting bugs Bug 1941655 and Bug 1943847 fixed.

I can confirm sync seems to be working in :

Firefox nighly : 136.0a1 (Build #2016070495), hg-fb62e31afd93+

You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: