Closed Bug 1613835 Opened 4 years ago Closed 4 years ago

Bookmarks sync fails with: MergeError: Failed to execute SQL string with code 1 (cannot start a transaction within a transaction)

Categories

(Firefox :: Sync, defect, P2)

Product:
Firefox
Component:
Sync
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
Firefox 75
Tracking Flags:
Tracking Status
firefox75 --- fixed

People

(Reporter: markh, Assigned: lina)

References

Details

Attachments

(2 files)

Bug 1613835 - Use a SQLite API call to check for in-progress transactions. r?mak!
47 bytes, text/x-phabricator-request
Details | Review
Bug 1613835 - Don't try to merge synced bookmarks if a transaction is already open. r?markh!
47 bytes, text/x-phabricator-request
Details | Review

This is from JR - my personal profile has also seen this 10 times in total starting Jan 11. Subsequent syncs work fine. If it turns out this is just a fact of life due to bad timing, we shouldn't report it as a failure.

1578367911204	Sync.Telemetry	TRACE	observed weave:engine:sync:start bookmarks
1578367911205	Sync.Engine.Bookmarks	DEBUG	Checking if server sync ID 99HiuIbpP1WN matches existing
1578367911205	Sync.Engine.Bookmarks.BookmarkSyncUtils	TRACE	Bookmarks sync ID up-to-date: {"existingSyncId":"99HiuIbpP1WN"}
1578367911208	Sync.Engine.Bookmarks.Mirror	TRACE	Sync ID up-to-date in mirror: {"existingSyncId":"99HiuIbpP1WN"}
1578367911208	Sync.Engine.Bookmarks	INFO	0 outgoing items pre-reconciliation
1578367911210	Sync.Engine.Bookmarks.Tracker	TRACE	onItemChanged: 1998, uri = "about:reader?url=https%3A%2F%2Fstep.state.gov%2FSTEP%2Fpages%2Findividuals%2FItinerary.aspx"
1578367911210	Sync.SyncScheduler	TRACE	Handling weave:engine:score:updated
1578367911211	Sync.Engine.Bookmarks	TRACE	Downloading & applying server changes
1578367911213	Sync.Engine.Bookmarks	INFO	Records: 0 applied, 0 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1578367911213	Sync.ErrorHandler	TRACE	Handling weave:engine:sync:applied
1578367911213	Sync.SyncScheduler	TRACE	Handling weave:engine:sync:applied
1578367911213	Sync.SyncScheduler	TRACE	Engine bookmarks successfully applied 0 items.
1578367911213	Sync.Telemetry	TRACE	observed weave:engine:sync:applied bookmarks
1578367911214	Sync.Engine.Bookmarks.Mirror	DEBUG	Merging bookmarks in Rust
1578367911227	Sync.Engine.Bookmarks.Mirror	DEBUG	Building local tree
1578367911238	Sync.Telemetry	TRACE	observed weave:engine:sync:step bookmarks
1578367911238	Sync.Engine.Bookmarks.Mirror	DEBUG	Building remote tree
1578367911250	Sync.Telemetry	TRACE	observed weave:engine:sync:step bookmarks
1578367911250	Sync.Telemetry	TRACE	observed weave:engine:validate:finish bookmarks
1578367911250	Sync.Engine.Bookmarks.Mirror	DEBUG	Building merged tree
1578367911252	Sync.Telemetry	TRACE	observed weave:engine:sync:step bookmarks
1578367911252	Sync.Engine.Bookmarks.Mirror	DEBUG	Applying merged tree
1578367911252	Sync.Engine.Bookmarks.BookmarkSyncUtils	DEBUG	pushChanges: Processed change records: {"weak":0,"skipped":0,"updated":0}
1578367911253	Sync.Engine.Bookmarks	ERROR	Bookmark sync failed, 336231.253000021s elapsed since last run; running Places maintenance



1578367911262	Sync.Engine.Bookmarks.Tracker	TRACE	onItemChanged: 1998, uri = "about:reader?url=https%3A%2F%2Fstep.state.gov%2FSTEP%2Fpages%2Findividuals%2FItinerary.aspx"
1578367911262	Sync.SyncScheduler	TRACE	Handling weave:engine:score:updated
1578367911362	Sync.SyncScheduler	TRACE	clients: score: 0
1578367911362	Sync.SyncScheduler	TRACE	prefs: score: 0
1578367911362	Sync.SyncScheduler	TRACE	passwords: score: 0
1578367911363	Sync.SyncScheduler	TRACE	tabs: score: 0
1578367911363	Sync.SyncScheduler	TRACE	bookmarks: score: 602
1578367911363	Sync.SyncScheduler	TRACE	addons: score: 0
1578367911363	Sync.SyncScheduler	TRACE	forms: score: 0
1578367911363	Sync.SyncScheduler	TRACE	history: score: 1
1578367911363	Sync.SyncScheduler	TRACE	extension-storage: score: 0
1578367911363	Sync.SyncScheduler	TRACE	Global score updated: 603
1578367911363	Sync.SyncScheduler	TRACE	_checkSync returned "".
1578367911363	Sync.SyncScheduler	DEBUG	Next sync in 3600000 ms. (why=schedule)
1578367911370	Sync.Telemetry	TRACE	observed weave:telemetry:event null
1578367911370	Sync.Telemetry	DEBUG	recording event: {"object":"maintenance","method":"run","value":"bookmarks"}
1578367911370	Sync.Engine.Bookmarks	TRACE	Event: weave:engine:sync:error
1578367911371	Sync.ErrorHandler	TRACE	Handling weave:engine:sync:error
1578367911371	Sync.Status	DEBUG	Status for engine bookmarks: error.engine.reason.unknown_fail
1578367911371	Sync.Status	DEBUG	Status.service: success.status_ok => error.sync.failed_partial
1578367911371	Sync.ErrorHandler	DEBUG	bookmarks failed: MergeError: Failed to execute SQL string with code 1 (cannot start a transaction within a transaction)(resource://gre/modules/SyncedBookmarksMirror.jsm:1417:5) JS Stack trace: MergeError@SyncedBookmarksMirror.jsm:1417:5
handleError@SyncedBookmarksMirror.jsm:779:22
1578367911371	Sync.SyncScheduler	TRACE	Handling weave:engine:sync:error
1578367911371	Sync.Telemetry	TRACE	observed weave:engine:sync:error bookmarks

The priority flag is not set for this bug.
:markh, could you have a look please?

For more information, please visit auto_nag documentation.

Flags: needinfo?(markh)
Assignee: nobody → lina
Status: NEW → ASSIGNED
Flags: needinfo?(markh)
Priority: -- → P2

Previously, mozIStorageConnection#transactionInProgress returned true
only if a transaction was started via beginTransaction(). This meant
that manually executing BEGIN, as Sqlite.jsm and the Rust bindings
do, wouldn't accurately report if a transaction was in progress.
Similarly, the flag wasn't accurate in cases where SQLite automatically
rolled back a transaction.

Fortunately, SQLite provides the sqlite3_get_autocommit() function,
which we can use to determine if a transaction is open or not. This
commit refactors the transactionInProgress getter, along with all
methods that depended on it, to use the SQLite API instead of tracking
that state on the connection. It also exposes this flag to Rust.

Occasionally, we might try to apply synced bookmarks when a transaction
is already in progress. Consider something like this:

  1. The user clicks the star button, which adds a bookmark to the
    default folder. Under the hood, this runs a transaction to
    completion—BEGIN, some INSERTs and UPDATEs, then COMMIT.
  2. The item-added observer notification kicks off a sync.
  3. The user, with the star UI still open, picks a new folder for the
    bookmark. This moves the bookmark under the hood.
  4. To move the bookmark, we run BEGIN on the Places connection's
    async thread. Remember, Sqlite.jsm runs async statements one at a
    time.
  5. Concurrently, the merge runnable is scheduled on the async thread.
    It's not aware of the Sqlite.jsm transaction queue, and doesn't
    know that a transaction for the move is already open.
  6. The merger tries to open its own transaction with BEGIN, fails
    noisly, and returns a "cannot start a transaction within a
    transaction" error back to the main thread.
  7. The move transaction started in (4) runs to completion, updating
    the new bookmark's parent and committing the changes.

This is a case of bad timing—retrying the sync once the user finishes
making changes will work—but reports errors in telemetry and logs.
This commit downgrades those to warnings.

Depends on D63732

Pushed by kcambridge@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/61fb3c36ea92
Use a SQLite API call to check for in-progress transactions. r=mak
https://hg.mozilla.org/integration/autoland/rev/4d2e14adc96b
Don't try to merge synced bookmarks if a transaction is already open. r=markh
Backout by shindli@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/b97b1c8552fb
Backed out 2 changesets for causing very frequent xpcshell failures in netwerk/test/unit/test_cookies_async_failure.js CLOSED TREE

I'm not sure, but I had a vague hunch this might've been caused by this block here. We check the auto-commit mode when we're not holding sharedDBMutex, and then grab it in beginTransactionInternal. In the most recent revision, I refactored {begin, commit, rollback}TransactionInternal to also take a proof of lock, and changed the block in mozStorageAsyncStatementExecution to take the sharedDBMutex first, before checking if a transaction is in progress or opening one if not.

I re-triggered the tests four times on Try (test_cookies_async_failure runs in X4 for opt; X2 for debug), and looks like they all pass now. Let's give this another go.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=128e9fc08169136dab7686e336874e7ced663c97

Flags: needinfo?(lina)
Pushed by kcambridge@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e3fd4a2ca5e3
Use a SQLite API call to check for in-progress transactions. r=mak
https://hg.mozilla.org/integration/autoland/rev/36989870cc80
Don't try to merge synced bookmarks if a transaction is already open. r=markh

https://hg.mozilla.org/mozilla-central/rev/e3fd4a2ca5e3
https://hg.mozilla.org/mozilla-central/rev/36989870cc80

Status: ASSIGNED → RESOLVED
Closed: 4 years ago
status-firefox75: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 75

Hello! Can you please tell us if manual testing is required here?

Hi Camelia! Nope, not required. 😊 Thanks!

Flags: qe-verify-
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: