Closed Bug 1450355 Opened 6 years ago Closed 1 month ago

Intermittent Assertion failure: thisDB->mCommonMetadata.version() == otherDB->mCommonMetadata.version(), at /builds/worker/workspace/build/src/dom/indexedDB/ActorsParent.cpp:22580

Categories

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

defect

Tracking

()

RESOLVED FIXED
125 Branch
Tracking Status
firefox68 --- disabled
firefox125 --- fixed

People

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

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files)

Nowadays this seems to be more a ccov build issue.

Over the last 7 days there are 38 failures present on this bug. These happen on linux64, linux32 and linux64-ccov.

Here is the most recent log example: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=240904982&repo=autoland&lineNumber=39434

[task 2019-04-17T11:09:33.170Z] 11:09:33 INFO - [Parent 5006, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/toolkit/components/antitracking/AntiTrackingCommon.cpp, line 400
[task 2019-04-17T11:09:33.178Z] 11:09:33 INFO - 1555499373173 Marionette DEBUG Accepted connection 1 from 127.0.0.1:59962
[task 2019-04-17T11:09:33.182Z] 11:09:33 INFO - 1555499373180 Marionette DEBUG 1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2019-04-17T11:09:33.192Z] 11:09:33 INFO - [Parent 5006, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/toolkit/components/antitracking/AntiTrackingCommon.cpp, line 400
[task 2019-04-17T11:09:33.212Z] 11:09:33 INFO - [Parent 5006, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/toolkit/components/antitracking/AntiTrackingCommon.cpp, line 400
[task 2019-04-17T11:09:33.228Z] 11:09:33 INFO - [Parent 5006, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/toolkit/components/antitracking/AntiTrackingCommon.cpp, line 400
[task 2019-04-17T11:09:33.237Z] 11:09:33 INFO - [Parent 5006, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/toolkit/components/antitracking/AntiTrackingCommon.cpp, line 400
[task 2019-04-17T11:09:33.414Z] 11:09:33 INFO - 1555499373405 Marionette TRACE [4294967297] Frame script loaded
[task 2019-04-17T11:09:33.418Z] 11:09:33 INFO - 1555499373414 Marionette TRACE [4294967297] Frame script registered
[task 2019-04-17T11:09:33.454Z] 11:09:33 INFO - 1555499373448 Marionette DEBUG 1 <- [1,1,null,{"sessionId":"61dcdb28-17c5-418f-a201-2da5fae2433a","capabilities":{"browserName":"firefox","browserVersion":"68.0a ... 8hJ3.tmpdrjO0Uexternal","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2019-04-17T11:09:33.482Z] 11:09:33 INFO - 1555499373478 Marionette DEBUG 1 -> [0,2,"WebDriver:DeleteSession",{}]
[task 2019-04-17T11:09:33.490Z] 11:09:33 INFO - 1555499373487 Marionette DEBUG 1 <- [1,2,null,{"value":null}]
[task 2019-04-17T11:09:33.494Z] 11:09:33 INFO - TEST-PASS | testing/marionette/harness/marionette_harness/tests/unit/test_profile_management.py TestSwitchProfileWithWorkspace.test_clone_existing_profile | took 11337ms
[task 2019-04-17T11:09:33.495Z] 11:09:33 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_profile_management.py TestSwitchProfileWithWorkspace.test_new_named_profile
[task 2019-04-17T11:09:33.503Z] 11:09:33 INFO - 1555499373496 Marionette DEBUG Closed connection 1
[task 2019-04-17T11:09:33.504Z] 11:09:33 INFO - 1555499373501 Marionette DEBUG Accepted connection 2 from 127.0.0.1:59964
[task 2019-04-17T11:09:33.512Z] 11:09:33 INFO - 1555499373510 Marionette DEBUG 2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2019-04-17T11:09:33.520Z] 11:09:33 INFO - Assertion failure: thisDB->mCommonMetadata.version() == otherDB->mCommonMetadata.version(), at /builds/worker/workspace/build/src/dom/indexedDB/ActorsParent.cpp:20913
[task 2019-04-17T11:09:33.520Z] 11:09:33 INFO - #01: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0x2d339c2]
[task 2019-04-17T11:09:33.520Z] 11:09:33 INFO - #02: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0x2d24c5d]
[task 2019-04-17T11:09:33.520Z] 11:09:33 INFO - #03: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0x2d20cd2]
[task 2019-04-17T11:09:33.522Z] 11:09:33 INFO - #04: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0x6eead2]
[task 2019-04-17T11:09:33.522Z] 11:09:33 INFO - #05: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0x6f1370]
[task 2019-04-17T11:09:33.523Z] 11:09:33 INFO - #06: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0xc61410]
[task 2019-04-17T11:09:33.523Z] 11:09:33 INFO - #07: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0xc19715]
[task 2019-04-17T11:09:33.533Z] 11:09:33 INFO - #08: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0xc19672]
[task 2019-04-17T11:09:33.534Z] 11:09:33 INFO - #09: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0x6ec2ed]
[task 2019-04-17T11:09:33.534Z] 11:09:33 INFO - #10: ???[/builds/worker/workspace/build/application/firefox/libnspr4.so +0x292b9]
[task 2019-04-17T11:09:33.535Z] 11:09:33 INFO - #11: ???[/lib/i386-linux-gnu/libpthread.so.0 +0x6295]
[task 2019-04-17T11:09:33.535Z] 11:09:33 INFO - 1555499373527 Marionette TRACE [4294967297] Frame script loaded
[task 2019-04-17T11:09:33.539Z] 11:09:33 INFO - ExceptionHandler::GenerateDump cloned child 5136
[task 2019-04-17T11:09:33.539Z] 11:09:33 INFO - ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2019-04-17T11:09:33.540Z] 11:09:33 INFO - ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[task 2019-04-17T11:09:33.556Z] 11:09:33 INFO - 1555499373546 Marionette TRACE [4294967297] Frame script registered
[task 2019-04-17T11:09:33.575Z] 11:09:33 INFO - [GFX1-]: Receive IPC close with reason=AbnormalShutdown
[task 2019-04-17T11:09:33.578Z] 11:09:33 INFO - [Child 5113, Chrome_ChildThread] WARNING: pipe error (3): Connection reset by peer: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 358
[task 2019-04-17T11:09:33.578Z] 11:09:33 INFO - Exiting due to channel error.
[task 2019-04-17T11:09:33.578Z] 11:09:33 INFO - Exiting due to channel error.
[task 2019-04-17T11:09:33.579Z] 11:09:33 INFO - Exiting due to channel error.
[task 2019-04-17T11:09:33.601Z] 11:09:33 INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_profile_management.py TestSwitchProfileWithWorkspace.test_new_named_profile | IOError: Process has been unexpectedly closed (Exit code: 11) (Reason: No data received over socket)
[task 2019-04-17T11:09:33.601Z] 11:09:33 INFO - Traceback (most recent call last):
[task 2019-04-17T11:09:33.602Z] 11:09:33 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 140, in run
[task 2019-04-17T11:09:33.603Z] 11:09:33 INFO - self.setUp()
[task 2019-04-17T11:09:33.604Z] 11:09:33 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_profile_management.py", line 227, in setUp
[task 2019-04-17T11:09:33.605Z] 11:09:33 INFO - super(TestSwitchProfileWithWorkspace, self).setUp()
[task 2019-04-17T11:09:33.606Z] 11:09:33 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_profile_management.py", line 63, in setUp
[task 2019-04-17T11:09:33.606Z] 11:09:33 INFO - super(ExternalProfileMixin, self).setUp()
[task 2019-04-17T11:09:33.608Z] 11:09:33 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_profile_management.py", line 45, in setUp

Flags: needinfo?(overholt)

Is this actionable, Jan?

Blocks: 1541370
Flags: needinfo?(overholt)
Priority: -- → P2

This has 67 failures in the last 7 days, on linux32,64 and osx all debug: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-04-17&endday=2019-04-24&tree=trunk&bug=1450355

Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=242229930&repo=autoland
It's now on the disable recommended bugs as it had 150+ failures in the last 30 days. Jan, is there something you could do here? Thanks.

Flags: needinfo?(jvarga)

Maybe Tom can investigate this.

Flags: needinfo?(jvarga) → needinfo?(shes050117)

Sure, I also hit this when pushing a patch to try [1].

Not really sure if it's related at this moment, but I also saw:

[task 2019-04-24T07:39:29.436Z] 07:39:29 INFO - [Parent 6262, IPDL Background] WARNING: NextVersionChangeTransactionSerialNumber doesn't match!: 'aLoggingInfo.nextVersionChangeTransactionSerialNumber() == loggingInfo->mLoggingInfo .nextVersionChangeTransactionSerialNumber()', file /builds/worker/workspace/build/src/dom/indexedDB/ActorsParent.cpp, line 12135
[task 2019-04-24T07:41:36.456Z] 07:41:36 INFO - [Parent 7635, IPDL Background] WARNING: NextVersionChangeTransactionSerialNumber doesn't match!: 'aLoggingInfo.nextVersionChangeTransactionSerialNumber() == loggingInfo->mLoggingInfo .nextVersionChangeTransactionSerialNumber()', file /builds/worker/workspace/build/src/dom/indexedDB/ActorsParent.cpp, line 12135

[1] https://treeherder.mozilla.org/#/jobs?repo=try&revision=adea133fd30d1de607e0257f6c59d8e4c8842776&selectedJob=242240760

Assignee: nobody → shes050117
Flags: needinfo?(shes050117)

I saw something strange:

So, I added a patch for logging the version of the metadata

[task 2019-04-25T08:21:21.339Z] 08:21:21 INFO - [TT] InitiateRequest op requestedVersion:1
[task 2019-04-25T08:21:21.339Z] 08:21:21 INFO - [TT] 0x7f0522783f70 Factory::AllocPBackgroundIDBFactoryRequestParent version:1
[task 2019-04-25T08:21:21.339Z] 08:21:21 INFO - [TT] FullIndexMetadata ctor :1
[task 2019-04-25T08:21:21.340Z] 08:21:21 INFO - [TT] OpenDatabaseOp ctor 0x7f05221e3c00 metadata version:1 param version:1
[task 2019-04-25T08:21:21.340Z] 08:21:21 INFO - 1556180481330 Marionette DEBUG Closed connection 1
[task 2019-04-25T08:21:21.340Z] 08:21:21 INFO - 1556180481334 Marionette DEBUG Accepted connection 2 from 127.0.0.1:60328
[task 2019-04-25T08:21:21.357Z] 08:21:21 INFO - 1556180481346 Marionette DEBUG 2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2019-04-25T08:21:21.359Z] 08:21:21 INFO - [TT] 0x7f05221e3c00 OpenDatabaseOp::AssertMetadataConsistency this v:0, other v:1 1

In this case, the version for the metadata held by OpenDatabaseOp is changed between the Operation is constructing and AssertMetadataConsistency. I wonder if the metadata is swapped or modified.

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=242519512&repo=try&lineNumber=38652

Whiteboard: [stockwell disable-recommended] → [stockwell needswork]

https://taskcluster-artifacts.net/ZBTwhOMeTx2kb8ASnrydrw/0/public/logs/live_backing.log

It seems it's because something was removed between subtests. The sequence is:

Subtest A start
OpenDatabase for some moz-extension in version 0
VersionChange for upgrading from 0 to 1 and writing the version to 1 for the table database
Subtest A end
Subtest B Start
OpenDatabase for some moz-extension in version 1 and expecting the version in the table database should be 1. (It's 0)
Hit the assertion

Generally successful case:
Subtest A start
OpenDatabase for some moz-extension in version 0
VersionChange for upgrading from 0 to 1 and writing the version to 1 for the table database
OpenDatabase for some moz-extension in version 1 and expecting the version in the table database should be 1. (It's 0)
Subtest A end

Whiteboard: [stockwell disable-recommended]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

There are 274 failures in the last 7 days.
:ttung , can you please take a look?

Recent log snippet:

[task 2019-05-02T05:39:20.299Z] 05:39:20 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_profile_management.py TestSwitchProfileWithWorkspace.test_new_named_profile
[task 2019-05-02T05:39:20.303Z] 05:39:20 INFO - 1556775560300 Marionette DEBUG Closed connection 1
[task 2019-05-02T05:39:20.321Z] 05:39:20 INFO - 1556775560309 Marionette DEBUG Accepted connection 2 from 127.0.0.1:47040
[task 2019-05-02T05:39:20.322Z] 05:39:20 INFO - Assertion failure: thisDB->mCommonMetadata.version() == otherDB->mCommonMetadata.version(), at /builds/worker/workspace/build/src/dom/indexedDB/ActorsParent.cpp:20922
[task 2019-05-02T05:39:20.323Z] 05:39:20 INFO - #01: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0x2dae088]
[task 2019-05-02T05:39:20.323Z] 05:39:20 INFO - #02: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0x2d9f32b]
[task 2019-05-02T05:39:20.324Z] 05:39:20 INFO - #03: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0x2d9b3a0]
[task 2019-05-02T05:39:20.325Z] 05:39:20 INFO - #04: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0x6f9572]
[task 2019-05-02T05:39:20.325Z] 05:39:20 INFO - #05: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0x6fbe10]
[task 2019-05-02T05:39:20.326Z] 05:39:20 INFO - #06: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0xc71e2c]
[task 2019-05-02T05:39:20.330Z] 05:39:20 INFO - #07: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0xc29c55]
[task 2019-05-02T05:39:20.331Z] 05:39:20 INFO - #08: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0xc29bb2]
[task 2019-05-02T05:39:20.332Z] 05:39:20 INFO - #09: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0x6f6d8d]
[task 2019-05-02T05:39:20.332Z] 05:39:20 INFO - #10: ???[/builds/worker/workspace/build/application/firefox/libnspr4.so +0x292b9]
[task 2019-05-02T05:39:20.333Z] 05:39:20 INFO - #11: ???[/lib/i386-linux-gnu/libpthread.so.0 +0x6295]
[task 2019-05-02T05:39:20.337Z] 05:39:20 INFO - ExceptionHandler::GenerateDump cloned child ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[task 2019-05-02T05:39:20.338Z] 05:39:20 INFO - 5257
[task 2019-05-02T05:39:20.338Z] 05:39:20 INFO - ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2019-05-02T05:39:20.370Z] 05:39:20 INFO - [GFX1-]: Receive IPC close with reason=AbnormalShutdown
[task 2019-05-02T05:39:20.371Z] 05:39:20 INFO - [Child 5235, Chrome_ChildThread] WARNING: pipe error (3): Connection reset by peer: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 358
[task 2019-05-02T05:39:20.373Z] 05:39:20 INFO - Exiting due to channel error.

Flags: needinfo?(shes050117)

I've been looking into this. I believe some of them are generated while I was investigating by logging. (I couldn't reproduce it on my local machine now)

Flags: needinfo?(shes050117)

Joel, can you take a look at this?

Flags: needinfo?(jmaher)

this is clearly a failure in:
testing/marionette/harness/marionette_harness/tests/unit/test_profile_management.py

found in this manifest:
https://searchfox.org/mozilla-central/source/testing/marionette/harness/marionette_harness/tests/unit/unit-tests.ini#88

can we disable this on osx/linux && debug?

Flags: needinfo?(jmaher)
Pushed by csabou@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/eda05cfa7212
disabled test_profile_management.py on osx/linux debug r=jmaher
Keywords: leave-open
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Assignee: ttung → nobody
Priority: P2 → P5
Assignee: nobody → ssengupta
Assignee: ssengupta → nobody
See Also: → 1547047
Severity: normal → S3

Is this still being reproduced?
The last report by Intermittent Failures Robot is about 4 years ago.

The test is still disabled:
https://searchfox.org/mozilla-central/rev/202c48686136360a23b73a49b611a19e64f3e1b8/testing/marionette/harness/marionette_harness/tests/unit/unit-tests.toml#113-117

Someone should revert the changes as landed here 5 years ago and check if the test is still failing.

Whiteboard: [stockwell disabled]
Pushed by csabou@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/683cf1ec26db
Re-enable test_profile_management.py because it is fixed. r=whimboo,intermittent-reviewers,webdriver-reviewers,ahal DONTBUILD
Assignee: nobody → csabou
Status: NEW → ASSIGNED
Status: ASSIGNED → RESOLVED
Closed: 1 month ago
Resolution: --- → FIXED
Target Milestone: --- → 125 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: