Closed Bug 1617011 Opened 2 years ago Closed 2 years ago

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()

Categories

(Toolkit :: Blocklist Implementation, defect, P5)

defect

Tracking

()

RESOLVED FIXED
mozilla75
Tracking Status
firefox75 --- fixed

People

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

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

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 - async
checkForEntries@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

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?

Flags: needinfo?(mathieu)

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 :(

Flags: needinfo?(mathieu)
Assignee: nobody → gijskruitbosch+bugs
Status: NEW → ASSIGNED
Pushed by gijskruitbosch@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/7f51f4442842
handle errors in get()/list() when they get called in the middle of shutdown, r=leplatrem
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla75
You need to log in before you can comment on or make changes to this bug.