Closed Bug 1713415 Opened 5 months ago Closed 4 months ago

Perma Windows ccov UntrustedModulesFixture.Serialize | Expected equality of these values:

Categories

(Firefox :: Launcher Process, defect, P5)

defect

Tracking

()

RESOLVED FIXED
91 Branch
Tracking Status
firefox-esr78 --- unaffected
firefox88 --- unaffected
firefox89 --- unaffected
firefox90 --- wontfix
firefox91 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, Whiteboard: [retriggered][stockwell unknown])

Attachments

(1 file)

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


[task 2021-05-29T00:19:18.468Z] 00:19:18     INFO -  TEST-START | UntrustedModulesFixture.Serialize
[task 2021-05-29T00:19:20.744Z] 00:19:20     INFO -  Received data. (pendingQueries=22)
[task 2021-05-29T00:19:20.766Z] 00:19:20     INFO -  Received data. (pendingQueries=22)
[task 2021-05-29T00:19:20.802Z] 00:19:20  WARNING -  TEST-UNEXPECTED-FAIL | UntrustedModulesFixture.Serialize | Expected equality of these values:
[task 2021-05-29T00:19:20.802Z] 00:19:20     INFO -    sInitLoadDataCollector.Collect(waitForTwo)
[task 2021-05-29T00:19:20.802Z] 00:19:20     INFO -      Which is: 4-byte object <04-40 00-80>
[task 2021-05-29T00:19:20.803Z] 00:19:20     INFO -    NS_OK
[task 2021-05-29T00:19:20.803Z] 00:19:20     INFO -      Which is: 4-byte object <00-00 00-00> @ z:/build/build/src/toolkit/xre/test/gtest/TestUntrustedModules.cpp:326
[task 2021-05-29T00:19:20.803Z] 00:19:20     INFO -  TestUntrustedModules_Dll1.dll:   6
[task 2021-05-29T00:19:20.804Z] 00:19:20     INFO -  TestUntrustedModules_Dll2.dll:   5
[task 2021-05-29T00:19:20.804Z] 00:19:20  WARNING -  TEST-UNEXPECTED-FAIL | UntrustedModulesFixture.Serialize | Value of: waitForTwo.Remains(kTestModules, {0, 0})
[task 2021-05-29T00:19:20.804Z] 00:19:20     INFO -    Actual: false
[task 2021-05-29T00:19:20.805Z] 00:19:20     INFO -  Expected: true @ z:/build/build/src/toolkit/xre/test/gtest/TestUntrustedModules.cpp:327
[task 2021-05-29T00:19:20.805Z] 00:19:20  WARNING -  TEST-UNEXPECTED-FAIL | UntrustedModulesFixture.Serialize | Expected equality of these values:
[task 2021-05-29T00:19:20.806Z] 00:19:20     INFO -    evt.mThreadId
[task 2021-05-29T00:19:20.806Z] 00:19:20     INFO -      Which is: 9552
[task 2021-05-29T00:19:20.806Z] 00:19:20     INFO -    ::GetCurrentThreadId()
[task 2021-05-29T00:19:20.806Z] 00:19:20     INFO -      Which is: 7152 @ z:/build/build/src/toolkit/xre/test/gtest/TestUntrustedModules.cpp:179
[task 2021-05-29T00:19:20.807Z] 00:19:20  WARNING -  TEST-UNEXPECTED-FAIL | UntrustedModulesFixture.Serialize | Expected equality of these values:
[task 2021-05-29T00:19:20.807Z] 00:19:20     INFO -    evt.mThreadId
[task 2021-05-29T00:19:20.807Z] 00:19:20     INFO -      Which is: 9552
[task 2021-05-29T00:19:20.807Z] 00:19:20     INFO -    ::GetCurrentThreadId()
[task 2021-05-29T00:19:20.808Z] 00:19:20     INFO -      Which is: 7152 @ z:/build/build/src/toolkit/xre/test/gtest/TestUntrustedModules.cpp:179
[task 2021-05-29T00:19:20.808Z] 00:19:20  WARNING -  TEST-UNEXPECTED-FAIL | UntrustedModulesFixture.Serialize | Expected equality of these values:
[task 2021-05-29T00:19:20.808Z] 00:19:20     INFO -    evt.mThreadId
[task 2021-05-29T00:19:20.809Z] 00:19:20     INFO -      Which is: 9552
[task 2021-05-29T00:19:20.809Z] 00:19:20     INFO -    ::GetCurrentThreadId()
[task 2021-05-29T00:19:20.809Z] 00:19:20     INFO -      Which is: 7152 @ z:/build/build/src/toolkit/xre/test/gtest/TestUntrustedModules.cpp:179
[task 2021-05-29T00:19:20.810Z] 00:19:20  WARNING -  TEST-UNEXPECTED-FAIL | UntrustedModulesFixture.Serialize | Expected equality of these values:
[task 2021-05-29T00:19:20.810Z] 00:19:20     INFO -    evt.mThreadId
[task 2021-05-29T00:19:20.811Z] 00:19:20     INFO -      Which is: 9552
[task 2021-05-29T00:19:20.811Z] 00:19:20     INFO -    ::GetCurrentThreadId()
[task 2021-05-29T00:19:20.811Z] 00:19:20     INFO -      Which is: 7152 @ z:/build/build/src/toolkit/xre/test/gtest/TestUntrustedModules.cpp:179
[task 2021-05-29T00:19:20.812Z] 00:19:20  WARNING -  TEST-UNEXPECTED-FAIL | UntrustedModulesFixture.Serialize | Expected equality of these values:
[task 2021-05-29T00:19:20.812Z] 00:19:20     INFO -    evt.mThreadId
[task 2021-05-29T00:19:20.812Z] 00:19:20     INFO -      Which is: 9552
[task 2021-05-29T00:19:20.812Z] 00:19:20     INFO -    ::GetCurrentThreadId()
[task 2021-05-29T00:19:20.813Z] 00:19:20     INFO -      Which is: 7152 @ z:/build/build/src/toolkit/xre/test/gtest/TestUntrustedModules.cpp:179
[task 2021-05-29T00:19:20.813Z] 00:19:20  WARNING -  TEST-UNEXPECTED-FAIL | UntrustedModulesFixture.Serialize | Expected equality of these values:
[task 2021-05-29T00:19:20.813Z] 00:19:20     INFO -    evt.mThreadId
[task 2021-05-29T00:19:20.813Z] 00:19:20     INFO -      Which is: 9552
[task 2021-05-29T00:19:20.814Z] 00:19:20     INFO -    ::GetCurrentThreadId()
[task 2021-05-29T00:19:20.814Z] 00:19:20     INFO -      Which is: 7152 @ z:/build/build/src/toolkit/xre/test/gtest/TestUntrustedModules.cpp:179
[task 2021-05-29T00:19:20.814Z] 00:19:20  WARNING -  TEST-UNEXPECTED-FAIL | UntrustedModulesFixture.Serialize | Expected equality of these values:
[task 2021-05-29T00:19:20.815Z] 00:19:20     INFO -    evt.mThreadId
[task 2021-05-29T00:19:20.815Z] 00:19:20     INFO -      Which is: 9552
[task 2021-05-29T00:19:20.815Z] 00:19:20     INFO -    ::GetCurrentThreadId()
[task 2021-05-29T00:19:20.816Z] 00:19:20     INFO -      Which is: 7152 @ z:/build/build/src/toolkit/xre/test/gtest/TestUntrustedModules.cpp:179

Regression from bug 1695817?

Flags: needinfo?(tkikuchi)
Summary: Perma tier2 UntrustedModulesFixture.Serialize | Expected equality of these values: → Perma Windows ccov UntrustedModulesFixture.Serialize | Expected equality of these values:

This started before bug 1695817 landed. The first two revisions 6adf3e04d40e2a9a and 98e96a91bbe49eb7 did not have the patches for bug 1695817.

The failure is the exact same as bug 1691684. Basically this is a time-out error that an expected async task was not completed within the maximum threshold. This can happen when a test machine's performance was slow. The fix is to increase the threshold.

Assignee: nobody → tkikuchi
Flags: needinfo?(tkikuchi)
See Also: → 1691684

This may be caused by a real bug in the third-party ping. Luckily this emerged because of the order change of GTest cases to run.

So far I narrowed down kMaxEvents in UntrustedModulesData::AddNewLoads is related to the problem. Basically we don't have to increase this value because if it's too small, the next processing task would process the remaining anyway, but it doesn't.

Whiteboard: [retriggered][stockwell needswork:owner]

We had the constant kMaxEvents which limits the maximum number of loading
events in UntrustedModulesData. Because we had a check for the number of
events in UntrustedModulesData::AddNewLoads where we already swapped
UntrustedModulesProcessor::mUnprocessedModuleLoads with a local variable,
when the array exceeds kMaxEvents, we discarded the remaining loading events.

The proposed fix is to check for kMaxEvents before swapping the unprocessed
events, so that the remaining events will be processed the next time.

This was caught by the UntrustedModulesFixture GTest. This test had
another test bug that it always expected modules were loaded in the main
thread except the predefined known modules. This is not correct because
the same process may have loaded a bunch of modules in the earlier GTests
such as graphics drivers in different threads. This patch includes a fix
for that bug as well.

Pushed by tkikuchi@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/a90edecdce6f
Don't discard the unprocessed loading events. r=aklotz
Status: NEW → RESOLVED
Closed: 4 months ago
Resolution: --- → FIXED
Target Milestone: --- → 91 Branch

Do we want to uplift this to 90?

Flags: needinfo?(tkikuchi)

With this bug, we lose some loading events in the third-party modules ping, but there is no impact on user experience. No need to uplift.

Flags: needinfo?(tkikuchi)
Backout by malexandru@mozilla.com:
https://hg.mozilla.org/mozilla-central/rev/582ea6610e8a
Backed out changeset a90edecdce6f for module checking crashes (bug 1717059). a=backout
Status: RESOLVED → REOPENED
Flags: needinfo?(tkikuchi)
Resolution: FIXED → ---
Target Milestone: 91 Branch → ---
Pushed by tkikuchi@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/176a32c4fda5
Don't discard the unprocessed loading events. r=aklotz
Status: REOPENED → RESOLVED
Closed: 4 months ago4 months ago
Resolution: --- → FIXED
Target Milestone: --- → 91 Branch
Flags: needinfo?(tkikuchi)
You need to log in before you can comment on or make changes to this bug.