Closed Bug 1637715 Opened 4 years ago Closed 2 years ago

Intermittent dom/indexedDB/test/test_upgrade_add_index.html | indexedDB error, 'AbortError': undefined

Categories

(Core :: Storage: IndexedDB, defect, P5)

defect

Tracking

()

RESOLVED DUPLICATE of bug 1777042
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

:iain , the failure started with Bug 1634135.
Can you please take a look?

Flags: needinfo?(iireland)

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.

Flags: needinfo?(iireland)
Flags: needinfo?(sgiesecke)
Regressed by: 1636316

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.

(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

Set release status flags based on info from the regressing bug 1636316

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

Flags: needinfo?(sgiesecke) → needinfo?(florian)

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

Flags: needinfo?(florian)

(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 the scheme = 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.

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

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

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.

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

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.

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

Flags: needinfo?(sgiesecke)
Whiteboard: [stockwell needswork]
Assignee: nobody → cbrindusan
Status: NEW → ASSIGNED

I've created a patch to disable this test if needed on Linux&Win10 / 64bits - opt.

Attachment #9149592 - Attachment description: Bug 1637715 - Disable test_upgrade_add_index.html for frequent failures on Linux and Windows. r=#intermittent-reviewers → Bug 1637715 - Disable test_upgrade_add_index.html for frequent failures on Linux and Windows. r?#intermittent-reviewers
Pushed by dluca@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/5f7897d45230
Disable test_upgrade_add_index.html for frequent failures on Linux and Windows. r=jmaher
Keywords: leave-open
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Flags: needinfo?(sgiesecke)
Regressed by: 1630982
Has Regression Range: --- → yes

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?

Flags: needinfo?(florian)
Attachment #9151161 - Attachment description: Bug 1637715 - update disabling condition to include mac and all win r?#intermittent-reviewers → Bug 1637715 - update disabling condition to include mac and all win r=jmaher DONTBUILD
Pushed by apavel@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/4c08b1cd8604
update disabling condition to include mac and all win r=jmaher DONTBUILD
Pushed by malexandru@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/b6ba55c8eec5
Add missing quotation mark to mac condition. a=fix

(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);
Flags: needinfo?(florian)

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.

Hi Simon, is this now actionable?

Flags: needinfo?(sgiesecke)

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

Assignee: cbrindusan → sgiesecke
Flags: needinfo?(sgiesecke)

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.

Depends on: 1652505
See Also: → 1653988
Assignee: sgiesecke → nobody
Status: ASSIGNED → NEW
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: