Closed Bug 1634093 Opened 4 years ago Closed 4 years ago

Intermittent services/sync/tests/unit/test_telemetry.js | test_deletion_request_ping - [test_deletion_request_ping : 265] A promise chain failed to handle a rejection: Error(s) encountered during statement execution: database mirror is locked

Categories

(Firefox :: Sync, defect, P5)

Product:
Firefox
Component:
Sync
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
Firefox 78
Tracking Flags:
Tracking Status
firefox77 --- fixed
firefox78 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: rfkelly)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Bug 1634093 - fix intermittent shutdown failures on sync telemetry test. r?lina
47 bytes, text/x-phabricator-request
Details | Review

Filed by: aciure [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=300006983&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/bdcrzMQtQHuYt9WRwmVl3A/runs/0/artifacts/public/logs/live_backing.log

[task 2020-04-29T15:57:05.388Z] 15:57:05 INFO - PID 18555 | WARNING: A blocker encountered an error while we were waiting.
[task 2020-04-29T15:57:05.389Z] 15:57:05 INFO - PID 18555 | Blocker: SyncedBookmarksMirror: finalize
[task 2020-04-29T15:57:05.389Z] 15:57:05 INFO - PID 18555 | Phase: Places Clients shutdown
[task 2020-04-29T15:57:05.389Z] 15:57:05 INFO - PID 18555 | State: {"steps":[{"step":"finalize","at":1588175816401}]}
[task 2020-04-29T15:57:05.390Z] 15:57:05 INFO - PID 18555 | WARNING: Error: Error(s) encountered during statement execution: database mirror is locked
[task 2020-04-29T15:57:05.390Z] 15:57:05 INFO - PID 18555 | WARNING: handleCompletion@resource://gre/modules/Sqlite.jsm:887:25
[task 2020-04-29T15:57:05.391Z] 15:57:05 INFO - PID 18555 | observe@resource://gre/modules/AsyncShutdown.jsm:554:16
[task 2020-04-29T15:57:05.391Z] 15:57:05 INFO - PID 18555 | _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:655:19
[task 2020-04-29T15:57:05.391Z] 15:57:05 INFO - PID 18555 | @-e:1:1
[task 2020-04-29T15:57:05.392Z] 15:57:05 INFO - PID 18555 | JavaScript error: resource://gre/modules/Sqlite.jsm, line 887: Error: Error(s) encountered during statement execution: database mirror is locked
[task 2020-04-29T15:57:05.392Z] 15:57:05 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "Error: Error(s) encountered during statement execution: database mirror is locked" {file: "resource://gre/modules/Sqlite.jsm" line: 887}]"
[task 2020-04-29T15:57:05.393Z] 15:57:05 INFO - PID 18555 | 1588175816414 Sync.Telemetry TRACE observed profile-before-change null
[task 2020-04-29T15:57:05.393Z] 15:57:05 INFO - PID 18555 | 1588175816415 Sync.Telemetry TRACE Not sending telemetry ping for self-hosted Sync user
[task 2020-04-29T15:57:05.393Z] 15:57:05 INFO - PID 18555 | 1588175816425 Sync.Engine.Prefs.Tracker TRACE stop().
[task 2020-04-29T15:57:05.394Z] 15:57:05 INFO - PID 18555 | 1588175816428 Sqlite.Connection WARN places.sqlite#0: Connection closed before committing the transaction.
[task 2020-04-29T15:57:05.394Z] 15:57:05 INFO - PID 18555 | console.error: (new Error("Connection closed before committing the transaction.", "resource://gre/modules/Sqlite.jsm", 681))
[task 2020-04-29T15:57:05.395Z] 15:57:05 INFO - PID 18555 | 1588175816431 Sync.Engine.Bookmarks TRACE Event: weave:engine:reset-client:error
[task 2020-04-29T15:57:05.395Z] 15:57:05 INFO - PID 18555 | 1588175816431 Sync.Service DEBUG Exception calling doResetClient: Error: Connection closed before committing the transaction.(resource://gre/modules/Sqlite.jsm:681:19) JS Stack trace: executeTransaction/promise</transactionPromise<@Sqlite.jsm:681:19
[task 2020-04-29T15:57:05.395Z] 15:57:05 INFO - PID 18555 | async*executeTransaction/promise<@Sqlite.jsm:700:9
[task 2020-04-29T15:57:05.396Z] 15:57:05 INFO - PID 18555 | _execute_test@head.js:654:19
[task 2020-04-29T15:57:05.396Z] 15:57:05 INFO - PID 18555 | @-e:1:1
[task 2020-04-29T15:57:05.397Z] 15:57:05 INFO - PID 18555 | 1588175816432 Sync.CollectionKeyManager INFO Clearing collection keys...
[task 2020-04-29T15:57:05.397Z] 15:57:05 INFO - PID 18555 | 1588175816434 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.nextSync
[task 2020-04-29T15:57:05.397Z] 15:57:05 INFO - PID 18555 | 1588175816434 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.lastPing
[task 2020-04-29T15:57:05.398Z] 15:57:05 INFO - PID 18555 | 1588175816434 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.prefs.lastSync
[task 2020-04-29T15:57:05.398Z] 15:57:05 INFO - PID 18555 | 1588175816435 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.engineStatusChanged.bogus
[task 2020-04-29T15:57:05.399Z] 15:57:05 INFO - PID 18555 | 1588175816435 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.client.syncID
[task 2020-04-29T15:57:05.399Z] 15:57:05 INFO - PID 18555 | 1588175816435 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.forms.lastSync
[task 2020-04-29T15:57:05.400Z] 15:57:05 INFO - PID 18555 | 1588175816435 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.history.lastSync
[task 2020-04-29T15:57:05.400Z] 15:57:05 INFO - PID 18555 | 1588175816435 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.clients.lastSync
[task 2020-04-29T15:57:05.401Z] 15:57:05 INFO - PID 18555 | 1588175816435 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.client.GUID
[task 2020-04-29T15:57:05.401Z] 15:57:05 INFO - PID 18555 | 1588175816436 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.username
[task 2020-04-29T15:57:05.402Z] 15:57:05 INFO - PID 18555 | 1588175816436 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.log.logger.engine
[task 2020-04-29T15:57:05.402Z] 15:57:05 INFO - PID 18555 | 1588175816436 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.log.logger
[task 2020-04-29T15:57:05.402Z] 15:57:05 INFO - PID 18555 | 1588175816436 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.tabs.lastSync
[task 2020-04-29T15:57:05.403Z] 15:57:05 INFO - PID 18555 | 1588175816436 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.passwords.lastSync
[task 2020-04-29T15:57:05.403Z] 15:57:05 INFO - PID 18555 | 1588175816436 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.bookmarks.lastSync
[task 2020-04-29T15:57:05.404Z] 15:57:05 INFO - PID 18555 | 1588175816437 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.lastversion
[task 2020-04-29T15:57:05.404Z] 15:57:05 INFO - PID 18555 | 1588175816438 Sync.LogManager DEBUG Flushing file log
[task 2020-04-29T15:57:05.405Z] 15:57:05 INFO - PID 18555 | 1588175816439 Sqlite.Connection INFO places.sqlite#0: Closed
[task 2020-04-29T15:57:05.405Z] 15:57:05 INFO - PID 18555 | 1588175816441 Sqlite.Connection INFO places.sqlite#1: Closed
[task 2020-04-29T15:57:05.406Z] 15:57:05 INFO - PID 18555 | 1588175816442 Sqlite.Connection INFO formhistory.sqlite#0: Closed
[task 2020-04-29T15:57:05.406Z] 15:57:05 INFO - PID 18555 | 1588175816493 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.cache.disk.amount_written
[task 2020-04-29T15:57:05.407Z] 15:57:05 WARNING - TEST-UNEXPECTED-FAIL | services/sync/tests/unit/test_telemetry.js | test_deletion_request_ping - [test_deletion_request_ping : 265] A promise chain failed to handle a rejection: Error(s) encountered during statement execution: database mirror is locked - stack: handleCompletion@resource://gre/modules/Sqlite.jsm:887:25
[task 2020-04-29T15:57:05.407Z] 15:57:05 INFO - observe@resource://gre/modules/AsyncShutdown.jsm:554:16
[task 2020-04-29T15:57:05.408Z] 15:57:05 INFO - _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:655:19
[task 2020-04-29T15:57:05.408Z] 15:57:05 INFO - @-e:1:1
[task 2020-04-29T15:57:05.408Z] 15:57:05 INFO - Rejection date: Wed Apr 29 2020 15:56:56 GMT+0000 (Coordinated Universal Time) - false == true
[task 2020-04-29T15:57:05.409Z] 15:57:05 INFO - resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:265
[task 2020-04-29T15:57:05.409Z] 15:57:05 INFO - /builds/worker/workspace/build/tests/xpcshell/head.js:_execute_test:664
[task 2020-04-29T15:57:05.410Z] 15:57:05 INFO - -e:null:1
[task 2020-04-29T15:57:05.410Z] 15:57:05 INFO - exiting test
[task 2020-04-29T15:57:05.410Z] 15:57:05 INFO - PID 18555 | JavaScript error: /builds/worker/workspace/build/tests/xpcshell/head.js, line 787: NS_ERROR_ABORT:
[task 2020-04-29T15:57:05.411Z] 15:57:05 INFO - PID 18555 | 1588175816735 Sync.ErrorHandler ERROR Failed to delete logs on reset: Error: OS.File has been shut down. Rejecting request to new_DirectoryIterator(resource://gre/modules/osfile/osfile_async_front.jsm:446:15) JS Stack trace: post/<@osfile_async_front.jsm:446:15
[task 2020-04-29T15:57:05.411Z] 15:57:05 INFO - PID 18555 | observe@AsyncShutdown.jsm:554:16

This seems likely to have been introduced by Bug 1604844, but I'm a bit lost as to how it fits together.

The async-shutdown logic is deliberately raise this as an uncaught error in order to cause tests to fail, as noted here.

The error itself originates in the places shutdown code, where we try to detach the mirror database. Which, yeah, does not handle errors from database operations at shutdown, but I assume that's on purpose.

The new test introduced Bug 1604844 triggers telemetry behavior by notifying various sync and fxa related events, like weave:service:ready. So my first guess is that one of these notifications is triggering unrelated behaviour in Firefox, possibly concurrent instances of it, and that's what's causing the shutdown failures.

Assignee: nobody → rfkelly

Running this test in a loop on my local machine, it seems to be caused by the test triggering the fxaccounts:onlogout notification. As a precaution I'm going to change all the notifications in this test to directly trigger the observer on the telemetry object itself, rather than routing them via the notification system.

Lina, could you please check my chain of reasoning here and make sure the proposed fix is sensible, and not just papering over some other issue in the shutdown of the bookmarks mirror?

Flags: needinfo?(lina)

Ooof, what a big ball of yarn, thanks for figuring it out! Your chain of reasoning sounds right, weave:service:ready and fxaccounts:onlogout in particular trigger a lot of cascading effects and spooky action-at-a-distance, from scheduling syncs to resetting local state (which initializes the mirror), and that's likely racing with the mirror shutting down.

You're totally right, the mirror intentionally doesn't catch errors in finalize, because we ordinarily do want to report them...just not in this case, and for this test. 😄

Thanks, Ryan!

Flags: needinfo?(lina)
Pushed by rkelly@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/bb8563a03d7e
fix intermittent shutdown failures on sync telemetry test. r=lina

https://hg.mozilla.org/mozilla-central/rev/bb8563a03d7e

Status: NEW → RESOLVED
Closed: 4 years ago
status-firefox78: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 78

Can this be uplifted to beta? Stumbled upon two failures of this on beta. No need for an uplift request if the answer is "yes" as it's a test-only change.

Flags: needinfo?(rfkelly)

Yes, this seems safe to uplift to beta.

Flags: needinfo?(rfkelly)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: