1775119 - Frequent TEST-UNEXPECTED-TIMEOUT | toolkit/components/extensions/test/xpcshell/test_ext_script_filenames.js | Test timed out

Status: RESOLVED FIXED

(WebExtensions :: General, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-06-20T15:43:54.667Z] 15:43:54     INFO -  TEST-START | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_script_filenames.js
[task 2022-06-20T15:48:54.725Z] 15:48:54  WARNING -  TEST-UNEXPECTED-TIMEOUT | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_script_filenames.js | Test timed out
[task 2022-06-20T15:48:54.725Z] 15:48:54     INFO -  TEST-INFO took 300057ms
[task 2022-06-20T15:48:54.725Z] 15:48:54     INFO -  >>>>>>>
[task 2022-06-20T15:48:54.725Z] 15:48:54     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2022-06-20T15:48:54.726Z] 15:48:54     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2022-06-20T15:48:54.726Z] 15:48:54     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2022-06-20T15:48:54.726Z] 15:48:54     INFO -  running event loop
[task 2022-06-20T15:48:54.727Z] 15:48:54     INFO -  xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_script_filenames.js | Starting setup check_remote
[task 2022-06-20T15:48:54.727Z] 15:48:54     INFO -  (xpcshell/head.js) | test check_remote pending (2)
[task 2022-06-20T15:48:54.728Z] 15:48:54     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_script_filenames.js | check_remote - [check_remote : 1] useRemoteWebExtensions matches - true == true

Comment 1

[Cosmin Sabou [:CosminS]]

Retriggers here.

Comment 2

[Beth Rennie [:beth] (she/her)]

This is not caused by bug 1773182. That bug added some new C++ helper functions which would not result in these failures.

Comment 3

[Intermittent Failures Robot]

18 failures in 518 pushes (0.035 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 11
• mozilla-central: 3
• comm-central: 4

Platform and build breakdown:

• windows7-32-qr: 6
  • opt: 6
• windows10-32-2004-qr: 4
  • debug: 3
  • opt: 1
• windows10-64-2004-qr: 4
  • debug: 2
  • opt: 2
• linux1804-64-tsan-qr: 1
  • opt: 1
• windows7-32-shippable-qr: 1
  • opt: 1
• windows10-64-2004-shippable-qr: 1
  • opt: 1
• windows10-32-2004-shippable-qr: 1
  • opt: 1

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

Comment 4

[Andreea Pavel [:apavel]]

Hi Shane, could you please assign someone to take a look at this?

There are 34 total failures in the last 2 days on

• windows7-32-qr opt
• windows10-64-2004-qr debug and opt
• windows10-64-2004-ccov-qr opt
• windows10-32-2004-qr debug
  Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=382110705&repo=mozilla-central&lineNumber=1896

Comment 5

[Intermittent Failures Robot]

26 failures in 538 pushes (0.048 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 10
• mozilla-central: 8
• comm-central: 7
• try: 1

Platform and build breakdown:

• windows10-32-2004-qr: 4
  • debug: 4
• windows10-64-2004-qr: 9
  • debug: 6
  • opt: 3
• windows7-32-qr: 2
  • opt: 2
• windows10-64-2004-ccov-qr: 3
  • opt: 3
• windows10-32-2004-shippable-qr: 1
  • opt: 1
• windows10-64-2004-shippable-qr: 2
  • opt: 2
• macosx1015-64-qr: 2
  • debug: 2
• windows10-64-2004-devedition-qr: 1
  • opt: 1
• windows7-32-shippable-qr: 1
  • opt: 1
• linux1804-64-tsan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1775119&startday=2022-06-21&endday=2022-06-21&tree=all

Comment 6

[Intermittent Failures Robot]

26 failures in 684 pushes (0.038 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 15
• mozilla-central: 11

Platform and build breakdown:

• windows10-64-2004-qr: 8
  • debug: 5
  • opt: 3
• windows10-32-2004-qr: 4
  • debug: 4
• linux1804-64-tsan-qr: 1
  • opt: 1
• macosx1015-64-qr: 3
  • debug: 3
• windows10-64-2004-ccov-qr: 3
  • opt: 3
• windows7-32-shippable-qr: 2
  • opt: 2
• windows10-64-2004-shippable-qr: 2
  • opt: 2
• windows7-32-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1775119&startday=2022-06-22&endday=2022-06-22&tree=all

Comment 7

[Luca Greco [:rpl] [:luca] [:lgreco]]

I've started to look into this today, I noticed that:

• I was not able to see it failing intermittently if the test was restricted to only the "in-process-webextensions" mode (mach try --tag in-process-webextensions --verify path/to/the/testfile)

• but it does fail pretty often (on the windows box where I was testing it it did fail after 3 runs of the --verify execution at most) with the "remote-webextensions" mode (mach try --tag remote-webextensions --verify path/to/the/testfile)

I was tweaking the test a bit for making it fail fast when the failure is being triggered, I have been also able to trigger it on linux both optimized and debug build, and I did verify that:

• when the failure is triggered it is because the inline script is intermittently failing to pass the csp hash check and it is blocked because identified as a csp policy violation (in my tweaked version I added a listener to the "securitypolicyviolation" event and that listener was logging a violation for the inline script consistently)

When the failure is triggered in a debug build I also noticed that the following assertion error is being logged:

[Child 2367268, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, false) failed with result 0x80070057 (NS_ERROR_ILLEGAL_VALUE): file /builds/worker/checkouts/gecko/dom/security/nsCSPUtils.cpp:991

right before the csp violation, and that points to the assertion here in nsCSPHashSrc::allows.

This seems to be pretty consistent too and so it seems worth digging into it a bit more.

Comment 8

[Luca Greco [:rpl] [:luca] [:lgreco]]

Hi Barret,
do you have some idea about what may be triggering that NS_ERROR_ILLEGAL_VALUE intermittently from that NS_NewCryptoHash call? (see comment 7)

Now that I've been able to trigger it on Linux I may also be able to record the failure with rr and dig into it a bit more, but in the meantime I wanted to ask you if you have some ideas (even just of some things that I could check in an rr recording to pin-point what is triggering this intermittently).

Comment 9

[Beth Rennie [:beth] (she/her)]

I was puzzled by this at first but it turns out NS_ERROR_ILLEGAL_VALUE == NS_ERROR_INVALID_ARG

NS_NewCryptoHash(const nsCString&, nsICryptoHash**) returns NS_ERROR_INVALID_ARG if either (a) an invalid algorithm is provided to nsCryptoHash::InitWithString or (b) the call to HASH_Create in nsCryptoHash::Init() returns nullptr. The latter case is due to NSS failures, I'm not an expert there.

Comment 10

[BugBot [:suhaib / :marco/ :calixte]]

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

Comment 11

[Intermittent Failures Robot]

19 failures in 640 pushes (0.03 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 12
• mozilla-central: 5
• comm-central: 1
• try: 1

Platform and build breakdown:

• windows10-32-2004-qr: 3
  • debug: 3
• windows10-64-2004-qr: 6
  • opt: 3
  • debug: 3
• linux1804-64-tsan-qr: 5
  • opt: 5
• linux1804-64-qr: 1
  • debug: 1
• windows10-64-2004-shippable-qr: 2
  • opt: 2
• windows10-64-2004-ccov-qr: 1
  • opt: 1
• windows7-32-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1775119&startday=2022-06-23&endday=2022-06-23&tree=all

Comment 12

[Luca Greco [:rpl] [:luca] [:lgreco]]

Attachment: Bug 1775119 - Tweak test_background_page_injects_scripts_inline to fail fast on unexpected csp violation. r?willdurand!

This patch doesn't fix the intermittent yet (the other patch attached applied the changes needed to prevent
nsCSPHashSrc::allows from failing intermittently when NSS was not initialized by the time we hit the CSP hash src
checks) but it does tweak the test a bit to:

• make it easier to change the test inline script without having to manually recomputing its sha256
  (which will make it easier to tweak the line script when needed, even just temporary changes applied
  for investigating an unexpected failure like for this bug).

• make sure the test fails fast if the inline script gets blocked by an unexpected csp violation (like the one
  tracked by this issue), by triggering an explicit failure and end the test immediately when the
  "securitypolicyviolation" event listener is hit.

Comment 13

[Luca Greco [:rpl] [:luca] [:lgreco]]

Attachment: Bug 1775119 - Make sure NSS is initialized before calling NS_NewCryptoHash from nsCSPHashSrc::allows. r?barret,ckerschb!

The intermittent failure tracked by Bug 1775119 is being triggered when nsCSPHashSrc::allows is called while NSS isn't
initialized yet (which is what makes NS_NewCryptoHash to return a NS_ERROR_ILLEGAL_VALUE nsresult).

After recording the test passing successfully with rr and looked into what did actually initialize NSS when the test pass,
it seems that the NSS initialization (at least in the xpcshell test environment) happened just as a side effect of a call
to Performance::Now() triggered by a call to Document::HasRecentlyStartedForegroundLoads().
This call is originated by the TaskController and so it may not be always triggered before the call to ns CSPHashSrc::allows
and when that happens the inline script triggers an unexpected CSP violation and it is not executed.

This also explains why the test was never failing in the in-process-webextensions, when the extensions are running on the
parent browser process NSS is likely already initialized by some other Gecko internals.

This patch adds an explicit call to EnsureNSSInitializedChromeOrContent right before the call to NS_NewCryptoHash, which is
making sure NSS is always initialized before trying to create a new crypto hash instance (which then makes the test to
pass consistently, included when executed with --verify).

Depends on D150241

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/030a01092ee3
Tweak test_background_page_injects_scripts_inline to fail fast on unexpected csp violation. r=willdurand
https://hg.mozilla.org/integration/autoland/rev/b14241477254
Make sure NSS is initialized before calling NS_NewCryptoHash from nsCSPHashSrc::allows. r=ckerschb

Comment 15

[Natalia Csoregi [:nataliaCs]]

https://hg.mozilla.org/mozilla-central/rev/030a01092ee3
https://hg.mozilla.org/mozilla-central/rev/b14241477254

Comment 16

[Intermittent Failures Robot]

100 failures in 3075 pushes (0.033 failures/push) were associated with this bug in the last 7 days.

This is the #8 most frequent failure this week.

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 52
• mozilla-central: 34
• comm-central: 12
• try: 2

Platform and build breakdown:

• windows10-32-2004-qr: 18
  • debug: 17
  • opt: 1
• windows10-64-2004-qr: 31
  • debug: 20
  • opt: 11
• windows7-32-qr: 11
  • opt: 11
• linux1804-64-tsan-qr: 9
  • opt: 9
• windows10-64-2004-shippable-qr: 8
  • opt: 8
• windows10-32-2004-shippable-qr: 2
  • opt: 2
• windows7-32-shippable-qr: 6
  • opt: 6
• windows10-64-2004-ccov-qr: 7
  • opt: 7
• macosx1015-64-qr: 5
  • debug: 5
• windows10-64-2004-devedition-qr: 1
  • opt: 1
• linux1804-64-qr: 1
  • debug: 1
• linux1804-64-asan-qr: 1
  • opt: 1

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

Comment 17

[BugBot [:suhaib / :marco/ :calixte]]

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