1617011 - Intermittent toolkit/mozapps/extensions/test/xpcshell/rs-blocklist/test_switchImplementations.js | test_switch_blocklist_implementations - [test_switch_blocklist_implementations : 265] A promise chain failed to handle a rejection: IndexedDB list()

Status: RESOLVED FIXED

(Toolkit :: Blocklist Implementation, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-02-20T21:12:33.168Z] 21:12:33 INFO - _run_next_test@/Users/cltbld/tasks/task_1582231817/build/tests/xpcshell/head.js:1567:38
[task 2020-02-20T21:12:33.168Z] 21:12:33 INFO - run@/Users/cltbld/tasks/task_1582231817/build/tests/xpcshell/head.js:735:9
[task 2020-02-20T21:12:33.168Z] 21:12:33 INFO - _do_main@/Users/cltbld/tasks/task_1582231817/build/tests/xpcshell/head.js:246:6
[task 2020-02-20T21:12:33.168Z] 21:12:33 INFO - _execute_test@/Users/cltbld/tasks/task_1582231817/build/tests/xpcshell/head.js:573:5
[task 2020-02-20T21:12:33.168Z] 21:12:33 INFO - @-e:1:1
[task 2020-02-20T21:12:33.168Z] 21:12:33 INFO - "
[task 2020-02-20T21:12:33.170Z] 21:12:33 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "IndexedDB UnknownErr: IDBDatabase.cpp:490"]"
[task 2020-02-20T21:12:33.170Z] 21:12:33 INFO - PID 5005 | JavaScript error: resource://services-common/kinto-offline-client.js, line 603: Error: IndexedDB list() IDBDatabase.transaction: Can't start IndexedDB transaction during shutdown
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "Error: IndexedDB list() IDBDatabase.transaction: Can't start IndexedDB transaction during shutdown" {file: "resource://services-common/kinto-offline-client.js" line: 603}]"
[task 2020-02-20T21:12:33.171Z] 21:12:33 WARNING - TEST-UNEXPECTED-FAIL | toolkit/mozapps/extensions/test/xpcshell/rs-blocklist/test_switchImplementations.js | test_switch_blocklist_implementations - [test_switch_blocklist_implementations : 265] A promise chain failed to handle a rejection: IndexedDB list() IDBDatabase.transaction: Can't start IndexedDB transaction during shutdown - stack: [4]</execute/<@resource://services-common/kinto-offline-client.js:384:66
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - execute@resource://services-common/kinto-offline-client.js:381:10
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - prepare@resource://services-common/kinto-offline-client.js:708:11
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - asynclist@resource://services-common/kinto-offline-client.js:870:18
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - list@resource://services-common/kinto-offline-client.js:2137:35
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - get@resource://services-settings/RemoteSettingsClient.jsm:351:44
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - asynccheckForEntries@resource://gre/modules/Blocklist.jsm:645:38
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - loadBlocklistAsync@resource://gre/modules/Blocklist.jsm:3125:20
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - _init/this[k]@resource://gre/modules/Blocklist.jsm:3184:43
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - test_switch_blocklist_implementations@/Users/cltbld/tasks/task_1582231817/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/rs-blocklist/test_switchImplementations.js:18:19
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - run_next_test/_run_next_test/<@/Users/cltbld/tasks/task_1582231817/build/tests/xpcshell/head.js:1567:22
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - _run_next_test@/Users/cltbld/tasks/task_1582231817/build/tests/xpcshell/head.js:1567:38
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - run@/Users/cltbld/tasks/task_1582231817/build/tests/xpcshell/head.js:735:9
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - _do_main@/Users/cltbld/tasks/task_1582231817/build/tests/xpcshell/head.js:246:6
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - _execute_test@/Users/cltbld/tasks/task_1582231817/build/tests/xpcshell/head.js:573:5
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - @-e:1:1
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - Rejection date: Thu Feb 20 2020 21:12:03 GMT+0000 (Greenwich Mean Time) - false == true
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:265
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - /Users/cltbld/tasks/task_1582231817/build/tests/xpcshell/head.js:_execute_test:668
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - -e:null:1
[task 2020-02-20T21:12:33.171Z] 21:12:33 INFO - exiting test

[task 2020-02-20T21:12:02.375Z] 21:12:02 INFO - TEST-START | toolkit/mozapps/extensions/test/xpcshell/rs-blocklist/test_switchImplementations.js

Comment 1

[:Gijs (he/him)]

The timing of this suggests it's related to now rejecting promises if there's an error in the worker in bug 1597688. Mathieu, can you take a look?

Comment 2

[Mathieu Leplatre [:leplatrem]]

I agree that timing is odd, but the stacktrace doesn't involve the worker at all. And this Can't start IndexedDB transaction during shutdown suggests that it's something else.

Nonetheless. I can reproduce locally using xpcshell-test --verify. And removing the connection closing in the worker (remember the «drive by» 😏) fixes the test failure.

But I don't think it's a bad thing to close that connection. But it has some side effects, as if the shutdown would happen earlier if we don't maintain that connection opened. I guess it's closed when the worker is terminated anyway.

Why would shutdown happen at the beginning of a test? First call to await Blocklist.loadBlocklistAsync(); on first task?

This is the stacktrace I get locally:

 0:42.37 FAIL test_switch_blocklist_implementations - [test_switch_blocklist_implementations : 265] A promise chain failed to handle a rejection: IndexedDB list() IDBDatabase.transaction: Can't start IndexedDB transaction during shutdown - stack: [4]</execute/<@resource://services-common/kinto-offline-client.js:384:66
execute@resource://services-common/kinto-offline-client.js:381:10
prepare@resource://services-common/kinto-offline-client.js:708:11
async*list@resource://services-common/kinto-offline-client.js:870:18
list@resource://services-common/kinto-offline-client.js:2137:35
get@resource://services-settings/RemoteSettingsClient.jsm:351:44
async*checkForEntries@resource://gre/modules/Blocklist.jsm:645:38
loadBlocklistAsync@resource://gre/modules/Blocklist.jsm:3125:20
_init/this[k]@resource://gre/modules/Blocklist.jsm:3184:43
test_switch_blocklist_implementations@/home/mathieu/Code/Mozilla/firefox/artifacts/obj-x86_64-pc-linux-gnu/_tests/xpcshell/toolkit/mozapps/extensions/test/xpcshell/rs-blocklist/test_switchImplementations.js:18:19
run_next_test/_run_next_test/<@/home/mathieu/Code/Mozilla/firefox/artifacts/testing/xpcshell/head.js:1567:22
_run_next_test@/home/mathieu/Code/Mozilla/firefox/artifacts/testing/xpcshell/head.js:1567:38
run@/home/mathieu/Code/Mozilla/firefox/artifacts/testing/xpcshell/head.js:735:9
_do_main@/home/mathieu/Code/Mozilla/firefox/artifacts/testing/xpcshell/head.js:246:6
_execute_test@/home/mathieu/Code/Mozilla/firefox/artifacts/testing/xpcshell/head.js:573:5
@-e:1:1

When enabling debug logs, I can see that network errors are thrown right before the failure. Is that expected?

 0:46.09 pid:20835 console.debug: services.settings: 
 0:46.09 pid:20835   blocklists/gfx sync status is network_error
 0:46.09 pid:20835 console.debug: services.settings: 
 0:46.09 pid:20835   blocklists/addons sync status is network_error
 0:46.09 pid:20835 console.debug: services.settings: 
 0:46.09 pid:20835   blocklists/plugins sync status is network_error
 0:16.00 INFO "CONSOLE_MESSAGE: (error) [JavaScript Error: "NetworkError when attempting to fetch resource." {file: "/home/mathieu/Code/Mozilla/firefox/artifacts/testing/xpcshell/head.js" line: 246}]
_do_main@/home/mathieu/Code/Mozilla/firefox/artifacts/testing/xpcshell/head.js:246:6
_execute_test@/home/mathieu/Code/Mozilla/firefox/artifacts/testing/xpcshell/head.js:573:5
@-e:1:1
"
 0:16.00 INFO "CONSOLE_MESSAGE: (error) [JavaScript Error: "NetworkError when attempting to fetch resource." {file: "/home/mathieu/Code/Mozilla/firefox/artifacts/testing/xpcshell/head.js" line: 246}]
_do_main@/home/mathieu/Code/Mozilla/firefox/artifacts/testing/xpcshell/head.js:246:6
_execute_test@/home/mathieu/Code/Mozilla/firefox/artifacts/testing/xpcshell/head.js:573:5
@-e:1:1
"
 0:16.00 INFO "CONSOLE_MESSAGE: (error) [JavaScript Error: "NetworkError when attempting to fetch resource." {file: "/home/mathieu/Code/Mozilla/firefox/artifacts/testing/xpcshell/head.js" line: 248}]
_do_main@/home/mathieu/Code/Mozilla/firefox/artifacts/testing/xpcshell/head.js:248:6
_execute_test@/home/mathieu/Code/Mozilla/firefox/artifacts/testing/xpcshell/head.js:573:5
@-e:1:1
"

Also, we got another crash with this same db.close() line in another patch (got backed out and not landed yet), and Baku said this:
It seems that this patch keeps an active connection when xpcom-shutdown-threads event is notified. We should terminate any storage connection before the shutdown.
https://bugzilla.mozilla.org/show_bug.cgi?id=1616052#c6

And this confuses me even more :(

Comment 3

[Intermittent Failures Robot]

1 failures in 4045 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• macosx1014-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1617011&startday=2020-02-17&endday=2020-02-23&tree=all

Comment 4

[:Gijs (he/him)]

Attachment: Bug 1617011 - handle errors in get()/list() when they get called in the middle of shutdown, r?leplatrem

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/7f51f4442842
handle errors in get()/list() when they get called in the middle of shutdown, r=leplatrem

Comment 6

[Andrei Ciure[:aciure]]

https://hg.mozilla.org/mozilla-central/rev/7f51f4442842

Comment 7

[Intermittent Failures Robot]

8 failures in 5233 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 5
• try: 2
• mozilla-central: 1

Platform breakdown:

• macosx1014-64-shippable: 8

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1617011&startday=2020-02-24&endday=2020-03-01&tree=all