1775472 - Frequent beta toolkit/components/extensions/test/xpcshell/test_ext_networkStatus.js | single tracking bug

Status: RESOLVED INCOMPLETE

(WebExtensions :: General, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-06-22T13:15:48.987Z] 13:15:48     INFO -  TEST-PASS | toolkit/components/cleardata/tests/unit/test_network_cache.js | took 136ms
[task 2022-06-22T13:15:48.993Z] 13:15:48     INFO -  TEST-START | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_networkStatus.js
[task 2022-06-22T13:15:49.375Z] 13:15:49  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_networkStatus.js | xpcshell return code: 0
[task 2022-06-22T13:15:49.375Z] 13:15:49     INFO -  TEST-INFO took 381ms
[task 2022-06-22T13:15:49.375Z] 13:15:49     INFO -  >>>>>>>
[task 2022-06-22T13:15:49.375Z] 13:15:49     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2022-06-22T13:15:49.375Z] 13:15:49     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2022-06-22T13:15:49.375Z] 13:15:49     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2022-06-22T13:15:49.375Z] 13:15:49     INFO -  running event loop
[task 2022-06-22T13:15:49.375Z] 13:15:49     INFO -  xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_networkStatus.js | Starting setup check_remote
[task 2022-06-22T13:15:49.375Z] 13:15:49     INFO -  (xpcshell/head.js) | test check_remote pending (2)
[task 2022-06-22T13:15:49.375Z] 13:15:49     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_networkStatus.js | check_remote - [check_remote : 1] useRemoteWebExtensions matches - true == true

Comment 1

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

[task 2022-06-22T13:15:49.379Z] 13:15:49     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_networkStatus.js | test_networkStatus - [test_networkStatus : 137] getLinkInfo should resolve to the same details received from onConnectionChanged - {"id":"undefined","status":"unknown","type":"unknown"} deepEqual {"id":"undefined","status":"unknown","type":"unknown"}
[task 2022-06-22T13:15:49.379Z] 13:15:49     INFO -  (xpcshell/head.js) | test run_next_test 2 pending (2)
[task 2022-06-22T13:15:49.379Z] 13:15:49     INFO -  (xpcshell/head.js) | test test_networkStatus finished (2)
[task 2022-06-22T13:15:49.379Z] 13:15:49     INFO -  xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_networkStatus.js | Starting test_networkStatus_permission
[task 2022-06-22T13:15:49.379Z] 13:15:49     INFO -  (xpcshell/head.js) | test test_networkStatus_permission pending (2)
[task 2022-06-22T13:15:49.379Z] 13:15:49     INFO -  "Getting initial pref value for "extensions.experiments.enabled""
[task 2022-06-22T13:15:49.379Z] 13:15:49     INFO -  "Setting pref "extensions.experiments.enabled": false"
[task 2022-06-22T13:15:49.379Z] 13:15:49     INFO -  "Extension attached"
[task 2022-06-22T13:15:49.379Z] 13:15:49     INFO -  (xpcshell/head.js) | test run_next_test 2 finished (2)
[task 2022-06-22T13:15:49.379Z] 13:15:49     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_networkStatus.js | test_networkStatus_permission - [test_networkStatus_permission : 1] Startup failed with privileged permission
[task 2022-06-22T13:15:49.380Z] 13:15:49     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "1655903749347	[e-mail]	ERROR	Loading extension '[e-mail]': Reading manifest: Using the privileged permission 'networkStatus' requires a privileged add-on. See https://mzl.la/3NS9KJd for more details about how to develop a privileged add-on." {file: "resource://gre/modules/Log.jsm" line: 725}]
[task 2022-06-22T13:15:49.380Z] 13:15:49     INFO -  append@resource://gre/modules/Log.jsm:725:12
[task 2022-06-22T13:15:49.380Z] 13:15:49     INFO -  log@resource://gre/modules/Log.jsm:381:16
[task 2022-06-22T13:15:49.380Z] 13:15:49     INFO -  error@resource://gre/modules/Log.jsm:389:10
[task 2022-06-22T13:15:49.380Z] 13:15:49     INFO -  _logMessage@resource://gre/modules/Extension.jsm:665:26
[task 2022-06-22T13:15:49.380Z] 13:15:49     INFO -  logError@resource://gre/modules/Extension.jsm:661:10
[task 2022-06-22T13:15:49.380Z] 13:15:49     INFO -  packagingError@resource://gre/modules/Extension.jsm:648:10
[task 2022-06-22T13:15:49.380Z] 13:15:49     INFO -  manifestError@resource://gre/modules/Extension.jsm:634:10
[task 2022-06-22T13:15:49.380Z] 13:15:49     INFO -  parseManifest@resource://gre/modules/Extension.jsm:1310:18
[task 2022-06-22T13:15:49.380Z] 13:15:49     INFO -  _do_main@/opt/worker/tasks/task_1655902544/build/tests/xpcshell/head.js:240:6
[task 2022-06-22T13:15:49.380Z] 13:15:49     INFO -  _execute_test@/opt/worker/tasks/task_1655902544/build/tests/xpcshell/head.js:597:5
[task 2022-06-22T13:15:49.380Z] 13:15:49     INFO -  @-e:1:1
[task 2022-06-22T13:15:49.380Z] 13:15:49     INFO -  "
[task 2022-06-22T13:15:49.380Z] 13:15:49     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "Reading manifest: Using the privileged permission 'networkStatus' requires a privileged add-on. See https://mzl.la/3NS9KJd for more details about how to develop a privileged add-on." {file: "resource://gre/modules/Extension.jsm" line: 672}]
[task 2022-06-22T13:15:49.380Z] 13:15:49     INFO -  ensureNoErrors@resource://gre/modules/Extension.jsm:672:13
[task 2022-06-22T13:15:49.380Z] 13:15:49     INFO -  loadManifest@resource://gre/modules/Extension.jsm:2621:10
[task 2022-06-22T13:15:49.380Z] 13:15:49     INFO -  _do_main@/opt/worker/tasks/task_1655902544/build/tests/xpcshell/head.js:240:6
[task 2022-06-22T13:15:49.381Z] 13:15:49     INFO -  _execute_test@/opt/worker/tasks/task_1655902544/build/tests/xpcshell/head.js:597:5
[task 2022-06-22T13:15:49.381Z] 13:15:49     INFO -  @-e:1:1
[task 2022-06-22T13:15:49.381Z] 13:15:49     INFO -  "
[task 2022-06-22T13:15:49.381Z] 13:15:49     INFO -  "CONSOLE_MESSAGE: (info) === console listener 0.2903979434121895 done ==="
[task 2022-06-22T13:15:49.381Z] 13:15:49     INFO -  "Matched expected console message: [JavaScript Error: "1655903749347	[e-mail]	ERROR	Loading extension '[e-mail]': Reading manifest: Using the privileged permission 'networkStatus' requires a privileged add-on. See https://mzl.la/3NS9KJd for more details about how to develop a privileged add-on." {file: "resource://gre/modules/Log.jsm" line: 725}]
[task 2022-06-22T13:15:49.381Z] 13:15:49     INFO -  append@resource://gre/modules/Log.jsm:725:12
[task 2022-06-22T13:15:49.381Z] 13:15:49     INFO -  log@resource://gre/modules/Log.jsm:381:16
[task 2022-06-22T13:15:49.381Z] 13:15:49     INFO -  error@resource://gre/modules/Log.jsm:389:10
[task 2022-06-22T13:15:49.381Z] 13:15:49     INFO -  _logMessage@resource://gre/modules/Extension.jsm:665:26
[task 2022-06-22T13:15:49.381Z] 13:15:49     INFO -  logError@resource://gre/modules/Extension.jsm:661:10
[task 2022-06-22T13:15:49.381Z] 13:15:49     INFO -  packagingError@resource://gre/modules/Extension.jsm:648:10
[task 2022-06-22T13:15:49.381Z] 13:15:49     INFO -  manifestError@resource://gre/modules/Extension.jsm:634:10
[task 2022-06-22T13:15:49.381Z] 13:15:49     INFO -  parseManifest@resource://gre/modules/Extension.jsm:1310:18
[task 2022-06-22T13:15:49.381Z] 13:15:49     INFO -  _do_main@/opt/worker/tasks/task_1655902544/build/tests/xpcshell/head.js:240:6
[task 2022-06-22T13:15:49.381Z] 13:15:49     INFO -  _execute_test@/opt/worker/tasks/task_1655902544/build/tests/xpcshell/head.js:597:5
[task 2022-06-22T13:15:49.381Z] 13:15:49     INFO -  @-e:1:1
[task 2022-06-22T13:15:49.381Z] 13:15:49     INFO -  "
[task 2022-06-22T13:15:49.381Z] 13:15:49     INFO -  "Clearing pref "extensions.experiments.enabled""
[task 2022-06-22T13:15:49.381Z] 13:15:49     INFO -  (xpcshell/head.js) | test run_next_test 3 pending (2)
[task 2022-06-22T13:15:49.381Z] 13:15:49     INFO -  (xpcshell/head.js) | test test_networkStatus_permission finished (2)
[task 2022-06-22T13:15:49.382Z] 13:15:49     INFO -  (xpcshell/head.js) | test run_next_test 3 finished (1)
[task 2022-06-22T13:15:49.382Z] 13:15:49     INFO -  exiting test
[task 2022-06-22T13:15:49.382Z] 13:15:49     INFO -  "Force a GC"
[task 2022-06-22T13:15:49.382Z] 13:15:49     INFO -  Error: Found unexpected files in temporary directory: generated-extension.xpi at resource://testing-common/AddonTestUtils.jsm:338
[task 2022-06-22T13:15:49.382Z] 13:15:49     INFO -  init/<@resource://testing-common/AddonTestUtils.jsm:338:15
[task 2022-06-22T13:15:49.382Z] 13:15:49     INFO -  _execute_test/<@/opt/worker/tasks/task_1655902544/build/tests/xpcshell/head.js:661:28
[task 2022-06-22T13:15:49.382Z] 13:15:49     INFO -  _execute_test@/opt/worker/tasks/task_1655902544/build/tests/xpcshell/head.js:673:16
[task 2022-06-22T13:15:49.382Z] 13:15:49     INFO -  @-e:1:1
[task 2022-06-22T13:15:49.382Z] 13:15:49     INFO -  PID 7888 | [Parent 7888, Main Thread] WARNING: ContentParent: id=12303a800 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3607
[task 2022-06-22T13:15:49.382Z] 13:15:49     INFO -  PID 7888 | [Parent 7888, Main Thread] WARNING: ContentParent: id=12303a800 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1808
[task 2022-06-22T13:15:49.382Z] 13:15:49     INFO -  PID 7888 | [Parent 7888, Main Thread] WARNING: ContentParent: id=12303a800 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1843
[task 2022-06-22T13:15:49.382Z] 13:15:49     INFO -  PID 7888 | [Parent 7888, Main Thread] WARNING: ContentParent: id=12303a800 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3709
[task 2022-06-22T13:15:49.382Z] 13:15:49     INFO -  <<<<<<<

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 9

Platform and build breakdown:

• macosx1100-64-shippable-qr: 6
  • opt: 6
• macosx1015-64-shippable-qr: 1
  • opt: 1
• windows10-64-2004-shippable-qr: 2
  • opt: 2

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

Comment 3

[Cosmin Sabou [:CosminS]]

This first failed on this beta-sim, today failed a lot and has only failed on try and since the merge is failing on beta too, trunk is unaffected. https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2022-06-21&endday=2022-06-28&tree=all&bug=1775472
I suspect the changes from https://hg.mozilla.org/mozilla-central/rev/d6f3b6db1b75c421c65654ed759f31fbe158554c might have something to do with this. Nicolas, could you please have a look over this one? Thank you.

Comment 4

[Nicolas Chevobbe [:nchevobbe]]

Bug 1764346 only added a mochitest, so I'm not sure how it could have an impact.
I was thinking maybe if the test would fail the browser toolbox might hang around, and we'd have an impact on other tests, but from this:
https://treeherder.mozilla.org/jobs?repo=try&group_state=expanded&revision=9e2c03399138034f7aa733fa5ed4f293090c2431&selectedTaskRun=YPRLfV1lR6OHU-O4U8Bjvw.0 I don't see any DevTools test being run, so I'd be very confused if my patch would cause this.

The failing test was modified in Bug 1771908, could it be that?

Comment 5

[Cosmin Sabou [:CosminS]]

Bug 1771908 reached central 14 days before the first fail so that's why I disregarded that, will dig some more.

Comment 6

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

I took a quick look to a sample of the most recent failures, and it seems that both on windows and macos the failure is being triggered after the last test task in that file has completed successfully but there is a xpi generated by a test that has not been removed as it should have been:

Error: Found unexpected files in temporary directory: generated-extension.xpi at resource://testing-common/AddonTestUtils.jsm:338  

(e.g. see https://treeherder.mozilla.org/logviewer?job_id=382570721&repo=try&lineNumber=4462 and https://treeherder.mozilla.org/logviewer?job_id=382444454&repo=try&lineNumber=5689)

I wouldn't expect Bug 1771908 to trigger this kind of intermittent failure, but tomorrow I'm going to see if I can give it a try to trigger the same failure locally and pinpoint what is going on (at least if Cosmin didn't already successfully bisect the regressing change by the time I'll get to it in my morning).

Comment 7

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

Unfortunately I've not been able to reproduce this locally (on a windows system, using mozilla beta artifact build of the 103 beta release).

Looking to that test file, the only thing that makes the last test case a bit "special" is that:

• the test task test_networkStatus_permission is explicitly expecting that extension.startup will not resolve successfully (instead it is expected to reject)
• that means that the test task can't end with the usual await extension.unload(); call which is making us sure that a test extension is fully unloaded and the generated xpi file to have been removed (before we are exiting the test and the callback registered by AddonTestUtils to confirm we didn't left any generated xpi file around to be executed)

With the options that the test is passing to ExtensionTestUtils.loadExtension, the generated xpi file:

• should have been created from the call to let extension = lazy.ExtensionTestCommon.generate(data); here in ExtensionXPCShellUtils.jsm
• then the Extension.prototype.cleanupGeneratedFile method to be called from here in Extension.prototype.startup in response to the manifest validation failure and remove the generated xpi file

The cleanupGeneratedFile method is async, and before trying to actually remove the file it has to broadcast a "Extension:FlushJarCache" message to all child processes to make sure we are not keeping the xpi file in use (otherwise removing it would fail on windows, but it that would be the case the Cu.reportError at the end of the promise chain should have logged an error, which I didn't see in the failure linked in this bug that I looked to, and so I'm excluding that from the possible causes).

The call to cleanupGeneratedFile in that try...catch (unlike the two calls originated from Extension.prototype.shutdown) isn't awaited nor returned to let the caller to await on the returned promise, and so there is a chance that this could be a race, and the test task may have been able to exit sooner than the cleanupGeneratedFile sync function to reach the file.remove(true) call chained to the call to broadcast the "Extension:FlushJarCache" message.

I took a look to the mercurial logs for some of these jsm files but I couldn't find any recent change that would make me think it could trigger an higher frequency of that condition, and so the actual change that may be triggering this high frequency intermittent may not be that visibly correlated to the extensions internals.

Comment 8

[Cosmin Sabou [:CosminS]]

Did a try run with Bug 1771173 backed out (parts of Bug 1773747 added there because of conflicts) and it looks like the failure doesn't repro anymore.
Mark, could you please have a look over this one? Thank you.

Comment 9

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

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

Comment 10

[Intermittent Failures Robot]

38 failures in 3312 pushes (0.011 failures/push) were associated with this bug in the last 7 days.

This is the #22 most frequent failure this week.

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

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

Repository breakdown:

• mozilla-beta: 33
• try: 5

Platform and build breakdown:

• windows10-64-2004-devedition-qr: 17
  • opt: 17
• windows10-64-2004-shippable-qr: 11
  • opt: 11
• macosx1015-64-devedition-qr: 3
  • opt: 3
• macosx1100-64-shippable-qr: 2
  • opt: 2
• macosx1015-64-shippable-qr: 5
  • opt: 5

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

Comment 11

[Mark Banner (:standard8)]

I tried doing a beta sim with partial backouts of the patch, but I believe it was inconclusive:

• XPIInstall backed out
  • One failure
• XPIDatabase backed out
  • No failures
• [No changes backed out)(https://treeherder.mozilla.org/jobs?repo=try&revision=279d2c65f0fbc739aa68dc67a3ae8116d8689a44&selectedTaskRun=ZzzB7ighQeCmO-0uA5uAKQ.0)
  • Two failures

So maybe backing out XPIDatabase changes helps, but I'm not convinced, there's not enough data points there to know.

I've been over the patches several times and I can't see anything that's missing or broken. The best thing I can think of is timing, but I believe there are no obvious changes that would affect timing.

Comment 12

[Cosmin Sabou [:CosminS]]

Worth mentioning that this fails only on shippable and devedition platforms both windows and macOS. Added some retriggers on the above backout pushes but the failure rate between them wasn't too different. It's somewhere between 25% and 50% on these builds.

• XPIInstall backed out
• XPIDatabase backed out

Comment 13

[Intermittent Failures Robot]

30 failures in 3072 pushes (0.01 failures/push) were associated with this bug in the last 7 days.

This is the #38 most frequent failure this week.

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

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

Repository breakdown:

• mozilla-beta: 20
• try: 10

Platform and build breakdown:

• windows10-64-2004-shippable-qr: 9
  • opt: 9
• windows10-64-2004-devedition-qr: 9
  • opt: 9
• macosx1100-64-shippable-qr: 7
  • opt: 7
• macosx1015-64-shippable-qr: 2
  • opt: 2
• macosx1015-64-devedition-qr: 2
  • opt: 2
• linux1804-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1775472&startday=2022-07-04&endday=2022-07-10&tree=all

Comment 14

[Intermittent Failures Robot]

21 failures in 3341 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 3
• mozilla-beta: 18

Platform and build breakdown:

• windows10-64-2004-shippable-qr: 8
  • opt: 8
• windows10-64-2004-devedition-qr: 5
  • opt: 5
• linux1804-64-devedition-qr: 1
  • opt: 1
• macosx1100-64-shippable-qr: 3
  • opt: 3
• macosx1015-64-shippable-qr: 1
  • opt: 1
• macosx1015-64-devedition-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1775472&startday=2022-07-11&endday=2022-07-17&tree=all

Comment 15

[Intermittent Failures Robot]

5 failures in 3497 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 1
• mozilla-release: 3
• try: 1

Platform and build breakdown:

• macosx1015-64-devedition-qr: 1
  • opt: 1
• windows10-64-2004-shippable-qr: 2
  • opt: 2
• macosx1100-64-shippable-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1775472&startday=2022-07-18&endday=2022-07-24&tree=all

Comment 16

[Intermittent Failures Robot]

4 failures in 3245 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-release: 4

Platform and build breakdown:

• windows10-64-2004-shippable-qr: 3
  • opt: 3
• macosx1100-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1775472&startday=2022-07-25&endday=2022-07-31&tree=all

Comment 17

[Intermittent Failures Robot]

3 failures in 3057 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-release: 3

Platform and build breakdown:

• windows10-64-2004-shippable-qr: 2
  • opt: 2
• macosx1100-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1775472&startday=2022-08-01&endday=2022-08-07&tree=all

Comment 18

[Intermittent Failures Robot]

3 failures in 3339 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-release: 3

Platform and build breakdown:

• macosx1015-64-shippable-qr: 1
  • opt: 1
• windows10-64-2004-shippable-qr: 2
  • opt: 2

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

Comment 19

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

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.