Closed Bug 1602683 Opened 4 years ago Closed 2 years ago

Intermittent dom/indexedDB/test/test_object_identity.html | Test timed out.

Categories

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

defect

Tracking

()

RESOLVED DUPLICATE of bug 1781614

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

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


[task 2019-12-09T23:42:30.944Z] 23:42:30 INFO - Worker: starting tests
[task 2019-12-09T23:42:30.945Z] 23:42:30 INFO - TEST-PASS | dom/indexedDB/test/test_object_identity.html | Unsupported function type: undefined
[task 2019-12-09T23:42:30.946Z] 23:42:30 INFO - TEST-PASS | dom/indexedDB/test/test_object_identity.html | Got same objectStores: undefined
[task 2019-12-09T23:42:30.946Z] 23:42:30 INFO - TEST-PASS | dom/indexedDB/test/test_object_identity.html | Got same indexes: undefined
[task 2019-12-09T23:42:30.947Z] 23:42:30 INFO - TEST-PASS | dom/indexedDB/test/test_object_identity.html | Got same objectStores: undefined
[task 2019-12-09T23:42:30.948Z] 23:42:30 INFO - TEST-PASS | dom/indexedDB/test/test_object_identity.html | Different objectStores: undefined
[task 2019-12-09T23:42:30.949Z] 23:42:30 INFO - TEST-PASS | dom/indexedDB/test/test_object_identity.html | Different objectStores: undefined
[task 2019-12-09T23:42:30.949Z] 23:42:30 INFO - TEST-PASS | dom/indexedDB/test/test_object_identity.html | Got same indexes: undefined
[task 2019-12-09T23:42:30.949Z] 23:42:30 INFO - TEST-PASS | dom/indexedDB/test/test_object_identity.html | Different indexes: undefined
[task 2019-12-09T23:42:30.949Z] 23:42:30 INFO - TEST-PASS | dom/indexedDB/test/test_object_identity.html | Different indexes: undefined
[task 2019-12-09T23:42:30.949Z] 23:42:30 INFO - TEST-PASS | dom/indexedDB/test/test_object_identity.html | Async/await tests shouldn't call finishTest(): undefined
[task 2019-12-09T23:42:30.949Z] 23:42:30 INFO - TEST-PASS | dom/indexedDB/test/test_object_identity.html | Worker finished
[task 2019-12-09T23:42:30.949Z] 23:42:30 INFO - Cleaning up the databases
[task 2019-12-09T23:42:30.949Z] 23:42:30 INFO - Buffered messages finished
[task 2019-12-09T23:42:30.949Z] 23:42:30 INFO - TEST-UNEXPECTED-FAIL | dom/indexedDB/test/test_object_identity.html | Test timed out.
[task 2019-12-09T23:42:30.949Z] 23:42:30 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:277:18
[task 2019-12-09T23:42:30.949Z] 23:42:30 INFO - reportError@SimpleTest/TestRunner.js:121:22
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:18
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - TestRunner.runTests/<@SimpleTest/TestRunner.js:388:20
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - promise callback
TestRunner.runTests@SimpleTest/TestRunner.js:375:50
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - RunSet.runtests@SimpleTest/setup.js:201:14
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - RunSet.runall@SimpleTest/setup.js:180:12
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - hookupTests@SimpleTest/setup.js:273:12
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:48:13
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:61:28
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - EventHandlerNonNullgetTestManifest@http://mochi.test:8888/manifestLibrary.js:57:3
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - hookup@SimpleTest/setup.js:253:20
[task 2019-12-09T23:42:30.950Z] 23:42:30 INFO - EventHandlerNonNull
@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true:11:1
[task 2019-12-09T23:42:31.690Z] 23:42:31 INFO - GECKO(3789) | MEMORY STAT | vsize 2673MB | residentFast 154MB | heapAllocated 21MB
[task 2019-12-09T23:42:31.694Z] 23:42:31 INFO - TEST-OK | dom/indexedDB/test/test_object_identity.html | took 307942ms

Summary: Intermittent dom/indexedDB/test/test_object_identity.html | Test timed out. → Intermittent dom/indexedDB/test/[test name] | Test timed out.

This Bug seems to regressed by Bug 1600906

Simon can you please take a look?

Flags: needinfo?(qlmatrix)
Regressed by: 1600906
Has Regression Range: --- → yes

(In reply to Arthur Iakab [arthur_iakab] from comment #1)

This Bug seems to regressed by Bug 1600906

Simon can you please take a look?

You probably meant me? I will give that a look.

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

Unfortunately, I haven't been able to reproduce this easily. What indications are there this was regressed by 1600906? Any specific patch that landed?

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

@Simon, since you have worked on dom/indexedDB I thought that Bug 1600906 could have caused this regression.
By looking at the code do you have any idea what could have caused these failures?

Flags: needinfo?(aiakab)

No, I don't see anything that might have caused that there. I don't think this is a regression from Bug 1600906. It might be a regression from other recent changes to dom/indexedDB, but there have been a lot. Has this happened multiple times recently?

I change the summary back to mention test_object_identity.html explicitly. There are several bugs for other specific test time outs, and I think it is rather confusing to have this very generic bug. The affected tests are not completely random in my current understanding, even if multiple failures have the same root cause.

Summary: Intermittent dom/indexedDB/test/[test name] | Test timed out. → Intermittent dom/indexedDB/test/test_object_identity.html | Test timed out.

On https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=287533885&repo=mozilla-central&lineNumber=4179, the test case execution before the first that timed out was OK (dom/indexedDB/test/test_objectStore_remove_values.html), but it showed several warnings, which might cause the timeouts on the following tests:

[task 2020-02-05T06:35:26.427Z] 06:35:26     INFO - GECKO(2158) | [Parent 2158, QuotaManager IO] WARNING: '!outputStream', file /builds/worker/workspace/build/src/dom/quota/ActorsParent.cpp, line 2396
[task 2020-02-05T06:35:26.428Z] 06:35:26     INFO - GECKO(2158) | [Parent 2158, QuotaManager IO] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/dom/quota/ActorsParent.cpp, line 8403
[task 2020-02-05T06:35:26.430Z] 06:35:26     INFO - GECKO(2158) | [Parent 2158, QuotaManager IO] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/dom/quota/ActorsParent.cpp, line 8265
[task 2020-02-05T06:35:26.431Z] 06:35:26     INFO - GECKO(2158) | [Parent 2158, QuotaManager IO] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/dom/quota/ActorsParent.cpp, line 8175
[task 2020-02-05T06:35:26.432Z] 06:35:26     INFO - GECKO(2158) | [Parent 2158, IPDL Background] WARNING: NextRequestSerialNumber doesn't match!: 'aLoggingInfo.nextRequestSerialNumber() == loggingInfo->mLoggingInfo.nextRequestSerialNumber()', file /builds/worker/workspace/build/src/dom/indexedDB/ActorsParent.cpp, line 12948
[task 2020-02-05T06:35:26.568Z] 06:35:26     INFO - GECKO(2158) | [Parent 2158, QuotaManager IO] WARNING: '!outputStream', file /builds/worker/workspace/build/src/dom/quota/ActorsParent.cpp, line 2396
[task 2020-02-05T06:35:26.570Z] 06:35:26     INFO - GECKO(2158) | [Parent 2158, QuotaManager IO] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/dom/quota/ActorsParent.cpp, line 8403
[task 2020-02-05T06:35:26.572Z] 06:35:26     INFO - GECKO(2158) | [Parent 2158, QuotaManager IO] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/dom/quota/ActorsParent.cpp, line 8265
[task 2020-02-05T06:35:26.573Z] 06:35:26     INFO - GECKO(2158) | [Parent 2158, QuotaManager IO] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/dom/quota/ActorsParent.cpp, line 8175

Going back in the log file I see during startup of GECKO(2158):

[task 2020-02-05T06:34:27.115Z] 06:34:27     INFO - GECKO(2158) | [Parent 2158, QuotaManager IO] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80630001: file /builds/worker/workspace/build/src/storage/mozStorageConnection.cpp, line 702
[task 2020-02-05T06:34:27.116Z] 06:34:27     INFO - GECKO(2158) | [Parent 2158, QuotaManager IO] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80630001: file /builds/worker/workspace/build/src/storage/mozStorageService.cpp, line 667
[task 2020-02-05T06:34:27.116Z] 06:34:27     INFO - GECKO(2158) | [Parent 2158, QuotaManager IO] WARNING: Received NS_ERROR_STORAGE_BUSY when attempting to open database '3128029391StpsleeTn+ddi.sqlite', retrying for up to 10 seconds: file /builds/worker/workspace/build/src/dom/indexedDB/ActorsParent.cpp, line 4137
[task 2020-02-05T06:34:27.273Z] 06:34:27     INFO - GECKO(2158) | [Parent 2158, QuotaManager IO] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80630001: file /builds/worker/workspace/build/src/storage/mozStorageConnection.cpp, line 702
[task 2020-02-05T06:34:27.273Z] 06:34:27     INFO - GECKO(2158) | [Parent 2158, QuotaManager IO] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80630001: file /builds/worker/workspace/build/src/storage/mozStorageService.cpp, line 667
[task 2020-02-05T06:34:27.273Z] 06:34:27     INFO - GECKO(2158) | [Parent 2158, QuotaManager IO] WARNING: Received NS_ERROR_STORAGE_BUSY when attempting to open database '993102857%25l2mFtthe.sxtesd%25n2iF.sqlite', retrying for up to 10 seconds: file /builds/worker/workspace/build/src/dom/indexedDB/ActorsParent.cpp, line 4137

Is this expected behavior? Do we see this in clean runs, too?

Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=351171429&repo=mozilla-central&lineNumber=11216

[task 2021-09-10T17:32:17.544Z] 17:32:17     INFO - TEST-PASS | dom/indexedDB/test/test_object_identity.html | Async/await tests shouldn't call finishTest(): undefined 
[task 2021-09-10T17:32:17.544Z] 17:32:17     INFO - TEST-PASS | dom/indexedDB/test/test_object_identity.html | Worker finished 
[task 2021-09-10T17:32:17.545Z] 17:32:17     INFO - Cleaning up the databases
[task 2021-09-10T17:32:17.545Z] 17:32:17     INFO - Buffered messages finished
[task 2021-09-10T17:32:17.545Z] 17:32:17     INFO - TEST-UNEXPECTED-FAIL | dom/indexedDB/test/test_object_identity.html | Test timed out. - 
[task 2021-09-10T17:32:18.409Z] 17:32:18     INFO - GECKO(29785) | MEMORY STAT | vsize 2764MB | residentFast 316MB | heapAllocated 6MB
[task 2021-09-10T17:32:18.418Z] 17:32:18     INFO - TEST-OK | dom/indexedDB/test/test_object_identity.html | took 309422ms
[task 2021-09-10T17:32:18.451Z] 17:32:18     INFO - TEST-START | dom/indexedDB/test/test_odd_result_order.html
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Depends on: 1777914
Status: REOPENED → RESOLVED
Closed: 3 years ago2 years ago
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.