Intermittent dom/indexedDB/test/test_upgrade_add_index.html | indexedDB error, 'AbortError': undefined
Categories
(Core :: Storage: IndexedDB, defect, P5)
Tracking
()
Tracking | Status | |
---|---|---|
firefox76 | --- | unaffected |
firefox77 | --- | unaffected |
firefox78 | --- | affected |
People
(Reporter: intermittent-bug-filer, Unassigned)
References
(Blocks 1 open bug, Regression)
Details
(Keywords: intermittent-failure, regression, Whiteboard: [stockwell disabled])
Attachments
(2 files)
Filed by: nbeleuzu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=302143309&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ODRIsWtwQTypBZ_jXnVtnw/runs/0/artifacts/public/logs/live_backing.log
[task 2020-05-13T18:15:56.120Z] 18:15:56 INFO - TEST-START | dom/indexedDB/test/test_upgrade_add_index.html
[task 2020-05-13T18:15:56.362Z] 18:15:56 INFO - GECKO(4368) | JavaScript error: , line 0: InternalError: bad serialized structured data (truncated)
[task 2020-05-13T18:15:56.362Z] 18:15:56 INFO - TEST-INFO | started process screentopng
[task 2020-05-13T18:15:56.524Z] 18:15:56 INFO - TEST-INFO | screentopng: exit 0
[task 2020-05-13T18:15:56.524Z] 18:15:56 INFO - Buffered messages logged at 18:15:56
[task 2020-05-13T18:15:56.524Z] 18:15:56 INFO - Running 'test_upgrade_add_index.js'
[task 2020-05-13T18:15:56.524Z] 18:15:56 INFO - Pushing preferences
[task 2020-05-13T18:15:56.524Z] 18:15:56 INFO - Pushing permissions
[task 2020-05-13T18:15:56.524Z] 18:15:56 INFO - Clearing old databases
[task 2020-05-13T18:15:56.526Z] 18:15:56 INFO - TEST-PASS | dom/indexedDB/test/test_upgrade_add_index.html | Unsupported function type
[task 2020-05-13T18:15:56.526Z] 18:15:56 INFO - Running test in a worker
[task 2020-05-13T18:15:56.526Z] 18:15:56 INFO - Worker: loading ["https://example.com/tests/dom/indexedDB/test/unit/test_upgrade_add_index.js"]
[task 2020-05-13T18:15:56.527Z] 18:15:56 INFO - Worker: starting tests
[task 2020-05-13T18:15:56.527Z] 18:15:56 INFO - TEST-PASS | dom/indexedDB/test/test_upgrade_add_index.html | Unsupported function type: undefined
[task 2020-05-13T18:15:56.527Z] 18:15:56 INFO - creating crypto key
[task 2020-05-13T18:15:56.528Z] 18:15:56 INFO - opening initial database
[task 2020-05-13T18:15:56.528Z] 18:15:56 INFO - add()ing crypto
[task 2020-05-13T18:15:56.529Z] 18:15:56 INFO - closing initial database
[task 2020-05-13T18:15:56.529Z] 18:15:56 INFO - opening database for upgrade to v2
[task 2020-05-13T18:15:56.530Z] 18:15:56 INFO - in upgrade, creating index
[task 2020-05-13T18:15:56.532Z] 18:15:56 INFO - Buffered messages finished
[task 2020-05-13T18:15:56.535Z] 18:15:56 INFO - TEST-UNEXPECTED-FAIL | dom/indexedDB/test/test_upgrade_add_index.html | indexedDB error, 'AbortError': undefined
[task 2020-05-13T18:15:56.536Z] 18:15:56 INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:299:16
[task 2020-05-13T18:15:56.536Z] 18:15:56 INFO - executeWorkerTestAndCleanUp/</worker.onmessage@https://example.com/tests/dom/indexedDB/test/helpers.js:780:24
[task 2020-05-13T18:15:56.537Z] 18:15:56 INFO - EventHandlerNonNull*executeWorkerTestAndCleanUp/<@https://example.com/tests/dom/indexedDB/test/helpers.js:776:7
[task 2020-05-13T18:15:56.537Z] 18:15:56 INFO - executeWorkerTestAndCleanUp@https://example.com/tests/dom/indexedDB/test/helpers.js:760:11
[task 2020-05-13T18:15:56.538Z] 18:15:56 INFO - testHarnessSteps@https://example.com/tests/dom/indexedDB/test/helpers.js:115:34
[task 2020-05-13T18:15:56.539Z] 18:15:56 INFO - nextTestHarnessStep@https://example.com/tests/dom/indexedDB/test/helpers.js:48:26
[task 2020-05-13T18:15:56.541Z] 18:15:56 INFO - TEST-PASS | dom/indexedDB/test/test_upgrade_add_index.html | Async/await tests shouldn't call finishTest(): undefined
[task 2020-05-13T18:15:56.542Z] 18:15:56 INFO - TEST-PASS | dom/indexedDB/test/test_upgrade_add_index.html | Worker finished
Comment 1•5 years ago
|
||
:iain , the failure started with Bug 1634135.
Can you please take a look?
Comment 2•5 years ago
|
||
The patches in bug 1634135 landed a couple days ago without causing this issue, and this testcase doesn't seem to have anything to do with regular expressions. Are you sure those patches are the right culprit?
It looks like this might be related to bug 1636316.
Comment hidden (Intermittent Failures Robot) |
Comment 4•5 years ago
|
||
Unfortunately, I haven't been able to reproduce this locally (yet). It seems to occur more frequently with an optimized build, and I used a debug build for now.
Comment 5•5 years ago
|
||
(In reply to Simon Giesecke [:sg] [he/him] from comment #4)
Unfortunately, I haven't been able to reproduce this locally (yet). It seems to occur more frequently with an optimized build, and I used a debug build for now.
If it's like bug 1636316, it could only be reproduced when running locally the whole folder of tests at once, ie ./mach mochitest dom/indexedDB/test/mochitest.ini
. Some explanations in bug 1636316 comment 7.
If you want to try to reproduce this behavior on a debug build, you'll need to remove this line: https://searchfox.org/mozilla-central/rev/9f074fab9bf905fad62e7cc32faf121195f4ba46/testing/specialpowers/content/SpecialPowersParent.jsm#632
Comment 6•5 years ago
|
||
Set release status flags based on info from the regressing bug 1636316
Comment hidden (Intermittent Failures Robot) |
Comment 8•5 years ago
|
||
(In reply to Florian Quèze [:florian] from comment #5)
(In reply to Simon Giesecke [:sg] [he/him] from comment #4)
Unfortunately, I haven't been able to reproduce this locally (yet). It seems to occur more frequently with an optimized build, and I used a debug build for now.
If it's like bug 1636316, it could only be reproduced when running locally the whole folder of tests at once, ie
./mach mochitest dom/indexedDB/test/mochitest.ini
. Some explanations in bug 1636316 comment 7.If you want to try to reproduce this behavior on a debug build, you'll need to remove this line: https://searchfox.org/mozilla-central/rev/9f074fab9bf905fad62e7cc32faf121195f4ba46/testing/specialpowers/content/SpecialPowersParent.jsm#632
I still have not being able to reproduce it locally :(
The cause of the abort seems to be https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=302143309&repo=autoland&lineNumber=6521, which is triggered here: https://searchfox.org/mozilla-central/rev/4166c15e2a99a23a9b38ad62c9fdfe8e5448b354/js/src/vm/StructuredClone.cpp#373. Without reproducing the issue, it is unclear what exactly happens in IndexedDB because of this error (if at all).
Depending on that, there may be different solutions, with decreasing order of probability:
- The cause of the
AbortError
must be ignored when running the test_upgrade_add_index.html test. - This might be the only correct behaviour. It must be ensured that the profile is cleared before running the test.
- Writing the original data in the test that is aborted must be changed in a way that does not produce this inconsistency.
Florian, have you any additional ideas how this can be reproduced with a debug build? In particular, a way to reproduce it that does not require running all tests but only a much smaller subset. This would maybe make it feasible to run under rr.
Comment 9•5 years ago
|
||
(In reply to Simon Giesecke [:sg] [he/him] from comment #8)
- This might be the only correct behaviour. It must be ensured that the profile is cleared before running the test.
Which files in the user profile might contain data that would affect the behavior of this test? It seems to me that this test uses its own database, at least for the non-worker part of it. For the worker part of it, it may be re-using "Splendid Test" as the database name. In an attempt to fix bug 1636316 I had tried changing that name (https://hg.mozilla.org/try/rev/2162d156c06dbdeb223209c8f4eaa6f453b4bd43) but that didn't help. Maybe this change could help here if that's the only problem left?
Florian, have you any additional ideas how this can be reproduced with a debug build? In particular, a way to reproduce it that does not require running all tests but only a much smaller subset. This would maybe make it feasible to run under rr.
If you could reproduce locally when running the whole manifest (not the whole folder of tests, running the mochitest part of it is enough, ie ./mach mochitest dom/indexedDB/test/mochitest.ini
), you might want to try saving the corrupted user profile between the 2 browser runs, and then run only the scheme = https
tests in your attempt to reproduce with rr.
Comment 10•5 years ago
|
||
(In reply to Florian Quèze [:florian] from comment #9)
(In reply to Simon Giesecke [:sg] [he/him] from comment #8)
- This might be the only correct behaviour. It must be ensured that the profile is cleared before running the test.
Which files in the user profile might contain data that would affect the behavior of this test?
Without reproducing this, it is hard to say, but as you point out, it's probably the Splendid Test
database files.
It seems to me that this test uses its own database, at least for the non-worker part of it. For the worker part of it, it may be re-using "Splendid Test" as the database name. In an attempt to fix bug 1636316 I had tried changing that name (https://hg.mozilla.org/try/rev/2162d156c06dbdeb223209c8f4eaa6f453b4bd43) but that didn't help. Maybe this change could help here if that's the only problem left?
Yes, indeed the Splendid Test
database name is used by many/all worker tests. Each test could use a separate database. Apparently there is the assumption in the tests that no such database exists at the start of each test (be it corrupted or not), which seems generally reasonable to me. I am not quite sure how to interpret your comment on this 'edge case' in https://bugzilla.mozilla.org/show_bug.cgi?id=1636316#c7. Do I understand it correctly that the behaviour changed with the changes from Bug 1630982? Is that intentional? Or could you ensure that the profile is cleared in this case as well?
Changing Splendid Test
to a test-specific name might mitigate this particular problem, but I guess for other reasons (--verify
runs, e.g.), clearing the profile seems to be the better approach.
Florian, have you any additional ideas how this can be reproduced with a debug build? In particular, a way to reproduce it that does not require running all tests but only a much smaller subset. This would maybe make it feasible to run under rr.
If you could reproduce locally when running the whole manifest (not the whole folder of tests, running the mochitest part of it is enough, ie
./mach mochitest dom/indexedDB/test/mochitest.ini
), you might want to try saving the corrupted user profile between the 2 browser runs, and then run only thescheme = https
tests in your attempt to reproduce with rr.
Unfortunately, I had no success reproducing it that way at all. I run MOZ_LOG=IndexedDB:4 ./mach mochitest --headless dom/indexedDB/test/mochitest.ini
.
Comment 11•5 years ago
|
||
(In reply to Simon Giesecke [:sg] [he/him] from comment #10)
Yes, indeed the
Splendid Test
database name is used by many/all worker tests.
The only other scheme=https
test has its own name for the worker database: https://searchfox.org/mozilla-central/rev/4166c15e2a99a23a9b38ad62c9fdfe8e5448b354/dom/indexedDB/test/unit/test_storage_manager_estimate.js#6
I am not quite sure how to interpret your comment on this 'edge case' in https://bugzilla.mozilla.org/show_bug.cgi?id=1636316#c7. Do I understand it correctly that the behaviour changed with the changes from Bug 1630982? Is that intentional? Or could you ensure that the profile is cleared in this case as well?
That we sometimes re-use a profile is an existing bug of runtests.py, that we could file and fix. The change of behavior with bug 1630982 is that now the re-used profile more often contains corrupted data.
I think a user profile with corrupted data is something that can happen whenever Firefox crashes, or the computer shuts down abruptly due to a power outage, or whatever. We shouldn't crash, and should be able to recover at the next run. So bug 1636316 is IMO an actual bug that we just uncovered accidentally. I'm less sure about this bug as I haven't looked closely.
Comment 12•5 years ago
|
||
(In reply to Florian Quèze [:florian] from comment #11)
(In reply to Simon Giesecke [:sg] [he/him] from comment #10)
Yes, indeed the
Splendid Test
database name is used by many/all worker tests.The only other
scheme=https
test has its own name for the worker database: https://searchfox.org/mozilla-central/rev/4166c15e2a99a23a9b38ad62c9fdfe8e5448b354/dom/indexedDB/test/unit/test_storage_manager_estimate.js#6
Ok. So as a quick fix, we could try changing the name to reduce the intermittent failure rate.
I am not quite sure how to interpret your comment on this 'edge case' in https://bugzilla.mozilla.org/show_bug.cgi?id=1636316#c7. Do I understand it correctly that the behaviour changed with the changes from Bug 1630982? Is that intentional? Or could you ensure that the profile is cleared in this case as well?
That we sometimes re-use a profile is an existing bug of runtests.py, that we could file and fix. The change of behavior with bug 1630982 is that now the re-used profile more often contains corrupted data.
I guess having a clean state for each test case is a general expectation.
I think a user profile with corrupted data is something that can happen whenever Firefox crashes, or the computer shuts down abruptly due to a power outage, or whatever. We shouldn't crash, and should be able to recover at the next run. So bug 1636316 is IMO an actual bug that we just uncovered accidentally. I'm less sure about this bug as I haven't looked closely.
Yes, Bug 1636316 was an actual bug (obviously a corrupted profile shouldn't cause a crash). This one might be a real bug as well, so preferredly I would like to reproduce the problem to analyze it. Since it's not a crash here, it might be the expected reaction to a corrupted profile, though.
Comment 13•5 years ago
|
||
I haven't checked all the comments here, so maybe I'm missing something, but all mochitests in dom/indexedDB call clearAllDatabases before and after each test. That functions clears all storage managed by QuotaManager (including all IndexedDB databases) for given origin/principal.
Comment 14•5 years ago
|
||
(In reply to Jan Varga [:janv] from comment #13)
I haven't checked all the comments here, so maybe I'm missing something, but all mochitests in dom/indexedDB call clearAllDatabases before and after each test. That functions clears all storage managed by QuotaManager (including all IndexedDB databases) for given origin/principal.
Ah ok. Interesting. But is it possible that there are leftover files in the profile that the QuotaManager is not aware of because the previous test was forcefully aborted?
Comment 15•5 years ago
|
||
Well, if some stuff on disk is totally broken, it can happen that even clearAllDatabases fails, and it seems we don't check the result of clearAllDatabases at the moment. So, yes, there's such possibility in theory. I would have to debug it more to give you a better answer.
Comment hidden (Intermittent Failures Robot) |
Comment 17•5 years ago
|
||
:sg , there are 130 failures in the last 4 days.
Most of them are on Linux&Win10 / 64bits - opt.
Should we disable test_upgrade_add_index.html on those platforms until there will be a fix?
Comment 18•5 years ago
|
||
Updated•5 years ago
|
Comment 19•5 years ago
|
||
I've created a patch to disable this test if needed on Linux&Win10 / 64bits - opt.
Updated•5 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment 21•5 years ago
|
||
Updated•5 years ago
|
Comment 22•5 years ago
|
||
bugherder |
Comment hidden (Intermittent Failures Robot) |
Updated•5 years ago
|
Comment 24•5 years ago
|
||
I can't reproduce this with an optimized build either.
Florian, if you are able to reproduce this, could you attach the profile causing the error to the bug?
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 28•5 years ago
|
||
Updated•5 years ago
|
Comment 29•5 years ago
|
||
Comment 30•5 years ago
|
||
Comment hidden (Intermittent Failures Robot) |
Comment 32•5 years ago
|
||
bugherder |
Comment hidden (Intermittent Failures Robot) |
Comment 34•5 years ago
|
||
(In reply to Simon Giesecke [:sg] [he/him] from comment #24)
I can't reproduce this with an optimized build either.
Florian, if you are able to reproduce this, could you attach the profile causing the error to the bug?
I managed to save a profile that cause the failure to reproduce 100%, and I reduced it. The failure happens if the previous test runs left these 2 prefs in the prefs.js
file in the profile folder:
user_pref("dom.indexedDB.dataThreshold", 0);
user_pref("dom.indexedDB.preprocessing", true);
Comment 35•5 years ago
|
||
Aha!
Nice finding, we need to set these prefs in our test harness code because we can't be sure that the default values are set.
Comment 37•5 years ago
|
||
(In reply to Jens Stutte [:jstutte] (PTO July 14-27) from comment #36)
Hi Simon, is this now actionable?
I'll give it a look.
Comment 38•5 years ago
|
||
I tried to activate this by setting the prefs mentioned in https://bugzilla.mozilla.org/show_bug.cgi?id=1637715#c34 via the mochitest.ini
but then the test isn't run at all:
0:08.16 GECKO(8958) [Parent 8958, IndexedDB #1] WARNING: Preprocessing for indexes not yet implemented!: file /home/simon/work/mozilla-unified/dom/indexedDB/ActorsParent.cpp, line 26036
0:08.16 GECKO(8958) [Parent 8958, IPDL Background] WARNING: Converting non-IndexedDB error code (0x80004001) to NS_ERROR_DOM_INDEXEDDB_UNKNOWN_ERR: file /home/simon/work/mozilla-unified/dom/indexedDB/ActorsParent.cpp, line 556
0:08.20 GECKO(8958) console.error: SearchEngineSelector: (new UnknownError("IndexedDB: main/search-config list() IndexedDB: execute() The operation failed for reasons unrelated to the database itself and not covered by any other error code.", "resource://services-settings/IDBHelpers.jsm", 24))
0:08.20 GECKO(8958) console.error: SearchEngineSelector: "Received empty search configuration!"
0:08.29 GECKO(8958) ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpf9zEyz.mozrunner/runtests_leaks_tab_pid9159.log
0:08.29 GECKO(8958) [9159, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /home/simon/work/mozilla-unified/tools/profiler/core/platform.cpp, line 245
0:08.32 GECKO(8958) [Parent 8958, IndexedDB #1] WARNING: Preprocessing for indexes not yet implemented!: file /home/simon/work/mozilla-unified/dom/indexedDB/ActorsParent.cpp, line 26036
0:08.32 GECKO(8958) [Parent 8958, IPDL Background] WARNING: Converting non-IndexedDB error code (0x80004001) to NS_ERROR_DOM_INDEXEDDB_UNKNOWN_ERR: file /home/simon/work/mozilla-unified/dom/indexedDB/ActorsParent.cpp, line 556
0:08.32 GECKO(8958) console.error: SearchEngineSelector: (new UnknownError("IndexedDB: main/search-config list() IndexedDB: execute() The operation failed for reasons unrelated to the database itself and not covered by any other error code.", "resource://services-settings/IDBHelpers.jsm", 24))
0:08.32 GECKO(8958) console.error: SearchEngineSelector: "Received empty search configuration!"
0:08.33 GECKO(8958) console.error: SearchService: "_init: failure initializing search:" (new TypeError("can't access property \"webExtension\", defaultEngine is undefined", "resource://gre/modules/SearchService.jsm", 1671))
0:08.33 GECKO(8958) JavaScript error: resource://gre/modules/SearchService.jsm, line 473: NS_ERROR_FAILURE: SearchService previously failed to initialize
0:08.33 GECKO(8958) JavaScript error: , line 0: uncaught exception: 2147500037
0:08.33 GECKO(8958) JavaScript error: resource://gre/modules/SearchService.jsm, line 2156: NS_ERROR_FAILURE: SearchService initialization failed
It's very annoying that the indexedDB test case cannot be run because some dependency of the test harness uses indexedDB, regardless of whether this failure of the SearchService is meaningful or not.
Before investigting this any further, this dependency should be removed.
Comment hidden (Intermittent Failures Robot) |
Updated•4 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Updated•3 years ago
|
Comment hidden (Intermittent Failures Robot) |
Updated•3 years ago
|
Updated•3 years ago
|
Description
•