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

Status: RESOLVED FIXED

(Firefox :: Launcher Process, defect, P5)

Description

[Treeherder Bug Filer]

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

Comment 1

[Intermittent Failures Robot]

13 failures in 2908 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 13

Platform and build breakdown:

• windows10-64-ccov-qr: 13
  • opt: 13

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1713415&startday=2021-05-24&endday=2021-05-30&tree=all

Comment 2

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Regression from bug 1695817?

Comment 3

[Toshihito Kikuchi [:toshi]]

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.

Comment 4

[Toshihito Kikuchi [:toshi]]

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.

Comment 5

[Intermittent Failures Robot]

13 failures in 3065 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 13

Platform and build breakdown:

• windows10-64-ccov-qr: 13
  • opt: 13

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1713415&startday=2021-05-31&endday=2021-06-06&tree=all

Comment 6

[Toshihito Kikuchi [:toshi]]

Attachment: Bug 1713415 - Don't discard the unprocessed loading events. r=aklotz

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.

Comment 7

[Intermittent Failures Robot]

19 failures in 3502 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 19

Platform and build breakdown:

• windows10-64-ccov-qr: 18
  • opt: 18
• windows10-32: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1713415&startday=2021-06-07&endday=2021-06-13&tree=all

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/a90edecdce6f
Don't discard the unprocessed loading events. r=aklotz

Comment 9

[Atila Butkovits]

https://hg.mozilla.org/mozilla-central/rev/a90edecdce6f

Comment 10

[Julien Cristau [:jcristau]]

Do we want to uplift this to 90?

Comment 11

[Toshihito Kikuchi [:toshi]]

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.

Comment 12

[Pulsebot]

Backout by [e-mail]:
https://hg.mozilla.org/mozilla-central/rev/582ea6610e8a
Backed out changeset a90edecdce6f for module checking crashes (bug 1717059). a=backout

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/176a32c4fda5
Don't discard the unprocessed loading events. r=aklotz

Comment 14

[Marian-Vasile Laza]

https://hg.mozilla.org/mozilla-central/rev/176a32c4fda5

Comment 15

[Intermittent Failures Robot]

9 failures in 2888 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 9

Platform and build breakdown:

• windows10-64-ccov-qr: 9
  • opt: 9

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1713415&startday=2021-06-14&endday=2021-06-20&tree=all