1761550 - Intermittent toolkit/components/extensions/test/mochitest/test_ext_scripting_contentScripts.html | [object Object] - Should not throw any errors

Status: RESOLVED FIXED

(WebExtensions :: General, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-03-25T19:50:02.762Z] 19:50:02     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_contentScripts.html | got expected script results[{"file":"script-1.js","value":"file contains iframe"},{"file":"script-2.js","value":"file contains iframe"},{"file":"script-2.js","value":"file contains img"},{"file":"script-3.js","value":"file contains img"},{"file":"script-4-2.js","value":"SCRIPT_4_INJECTED"},{"file":"script-5.js","value":"file contains iframe"}] 
[task 2022-03-25T19:50:02.762Z] 19:50:02     INFO - add_task | Leaving test test_registerContentScripts_js
[task 2022-03-25T19:50:02.763Z] 19:50:02     INFO - add_task | Entering test test_registerContentScripts_are_not_unregistered
[task 2022-03-25T19:50:02.763Z] 19:50:02     INFO - Extension loaded
[task 2022-03-25T19:50:02.764Z] 19:50:02     INFO - Buffered messages logged at 19:50:01
[task 2022-03-25T19:50:02.764Z] 19:50:02     INFO - add_task | Leaving test test_registerContentScripts_are_not_unregistered
[task 2022-03-25T19:50:02.764Z] 19:50:02     INFO - add_task | Entering test test_scripts_dont_run_after_shutdown
[task 2022-03-25T19:50:02.765Z] 19:50:02     INFO - Extension loaded
[task 2022-03-25T19:50:02.765Z] 19:50:02     INFO - Extension loaded
[task 2022-03-25T19:50:02.766Z] 19:50:02     INFO - Buffered messages logged at 19:50:02
[task 2022-03-25T19:50:02.766Z] 19:50:02     INFO - add_task | Leaving test test_scripts_dont_run_after_shutdown
[task 2022-03-25T19:50:02.767Z] 19:50:02     INFO - add_task | Entering test test_registerContentScripts_with_wrong_matches
[task 2022-03-25T19:50:02.767Z] 19:50:02     INFO - Extension loaded
[task 2022-03-25T19:50:02.768Z] 19:50:02     INFO - Extension loaded
[task 2022-03-25T19:50:02.768Z] 19:50:02     INFO - Buffered messages finished
[task 2022-03-25T19:50:02.769Z] 19:50:02     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_scripting_contentScripts.html | [object Object] - Should not throw any errors
[task 2022-03-25T19:50:02.769Z] 19:50:02     INFO -     add_task/nextTick/<@SimpleTest/SimpleTest.js:2103:26
[task 2022-03-25T19:50:02.769Z] 19:50:02     INFO - GECKO(2708) | MEMORY STAT | vsize 533MB | vsizeMaxContiguous 1293MB | residentFast 70MB | heapAllocated 9MB
[task 2022-03-25T19:50:02.770Z] 19:50:02     INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_scripting_contentScripts.html | took 2394ms
[task 2022-03-25T19:50:02.770Z] 19:50:02     INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript.html

Comment 1

[Iulian Moraru]

Hi Tomislav! Can you please take a look at this? This seems to be caused by your recent changes from Bug 1745819.
Thank you!
Backfill range

Comment 2

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

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

Comment 3

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

:zombie, since you are the author of the regressor, bug 1745819, could you take a look?
For more information, please visit auto_nag documentation.

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 5
• mozilla-central: 3
• try: 1

Platform and build breakdown:

• windows10-32-2004-qr: 3
  • opt: 3
• windows10-64-2004-qr: 1
  • opt: 1
• windows10-64-2004-shippable-qr: 4
  • opt: 4
• windows10-32-2004-shippable-qr: 1
  • opt: 1

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

Comment 5

[Natalia Csoregi [:nataliaCs]]

Update:

There have been 34 failures within the last 7 days:

• 5 failures on Windows 10 x86 2004 WebRender opt
• 5 failures on Windows 10 x86 2004 WebRender Shippable opt
• 13 failures on Windows 10 x64 2004 WebRender opt
• 11 failures on Windows 10 x64 2004 WebRender Shippable opt

Recent failure: https://treeherder.mozilla.org/logviewer?job_id=373239786&repo=autoland&lineNumber=14036

[task 2022-04-03T23:23:26.338Z] 23:23:26     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_contentScripts.html | got expected script results[{"file":"script-1.js","value":"file contains iframe"},{"file":"script-2.js","value":"file contains iframe"},{"file":"script-2.js","value":"file contains img"},{"file":"script-3.js","value":"file contains img"},{"file":"script-4-2.js","value":"SCRIPT_4_INJECTED"},{"file":"script-5.js","value":"file contains iframe"}] 
[task 2022-04-03T23:23:26.339Z] 23:23:26     INFO - add_task | Leaving test test_registerContentScripts_js
[task 2022-04-03T23:23:26.339Z] 23:23:26     INFO - add_task | Entering test test_registerContentScripts_are_not_unregistered
[task 2022-04-03T23:23:26.339Z] 23:23:26     INFO - Extension loaded
[task 2022-04-03T23:23:26.339Z] 23:23:26     INFO - Buffered messages logged at 23:23:25
[task 2022-04-03T23:23:26.340Z] 23:23:26     INFO - add_task | Leaving test test_registerContentScripts_are_not_unregistered
[task 2022-04-03T23:23:26.340Z] 23:23:26     INFO - add_task | Entering test test_scripts_dont_run_after_shutdown
[task 2022-04-03T23:23:26.340Z] 23:23:26     INFO - Extension loaded
[task 2022-04-03T23:23:26.341Z] 23:23:26     INFO - Extension loaded
[task 2022-04-03T23:23:26.341Z] 23:23:26     INFO - add_task | Leaving test test_scripts_dont_run_after_shutdown
[task 2022-04-03T23:23:26.341Z] 23:23:26     INFO - add_task | Entering test test_registerContentScripts_with_wrong_matches
[task 2022-04-03T23:23:26.342Z] 23:23:26     INFO - Extension loaded
[task 2022-04-03T23:23:26.342Z] 23:23:26     INFO - Extension loaded
[task 2022-04-03T23:23:26.342Z] 23:23:26     INFO - Buffered messages finished
[task 2022-04-03T23:23:26.343Z] 23:23:26     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_scripting_contentScripts.html | [object Object] - Should not throw any errors
[task 2022-04-03T23:23:26.343Z] 23:23:26     INFO -     add_task/nextTick/<@SimpleTest/SimpleTest.js:2103:26
[task 2022-04-03T23:23:26.343Z] 23:23:26     INFO - GECKO(2984) | MEMORY STAT | vsize 2103656MB | vsizeMaxContiguous 69219190MB | residentFast 59MB | heapAllocated 8MB
[task 2022-04-03T23:23:26.344Z] 23:23:26     INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_scripting_contentScripts.html | took 2074ms

Comment 6

[Intermittent Failures Robot]

40 failures in 3323 pushes (0.012 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:

• autoland: 29
• try: 6
• mozilla-central: 5

Platform and build breakdown:

• windows10-64-2004-qr: 13
  • opt: 13
• windows10-64-2004-shippable-qr: 11
  • opt: 11
• windows10-32-2004-qr: 8
  • opt: 8
• windows10-32-2004-shippable-qr: 8
  • opt: 8

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

Comment 7

[Atila Butkovits]

There have been 42 failures in the last 7 days.

Happens on:

• windows10-32-2004-qr opt
• windows10-32-2004-shippable-qr opt
• windows10-64-2004-qr opt
• windows10-64-2004-shippable-qr opt.

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=373979712&repo=autoland&lineNumber=12265

Tomislav, could you look into this?
Thanks

Comment 8

[Intermittent Failures Robot]

47 failures in 2922 pushes (0.016 failures/push) were associated with this bug in the last 7 days.

This is the #13 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:

• autoland: 32
• mozilla-beta: 4
• mozilla-central: 8
• try: 3

Platform and build breakdown:

• windows10-64-2004-qr: 17
  • opt: 17
• windows10-32-2004-qr: 7
  • opt: 7
• windows10-32-2004-shippable-qr: 13
  • opt: 13
• windows10-64-2004-shippable-qr: 8
  • opt: 8
• windows10-64-2004-devedition-qr: 2
  • opt: 2

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

Comment 9

[Intermittent Failures Robot]

41 failures in 2948 pushes (0.014 failures/push) were associated with this bug in the last 7 days.

This is the #16 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:

• autoland: 28
• mozilla-central: 6
• try: 4
• mozilla-beta: 3

Platform and build breakdown:

• windows10-64-2004-qr: 12
  • opt: 12
• windows10-32-2004-shippable-qr: 5
  • opt: 5
• windows10-32-2004-qr: 8
  • opt: 8
• windows10-64-2004-shippable-qr: 13
  • opt: 13
• windows10-64-2004-devedition-qr: 3
  • opt: 3

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

Comment 10

[Marian-Vasile Laza]

There have been 36 total failures in the last 7 days, recent failure log.
Affected platforms are:

• windows10-32-2004-qr
• windows10-32-2004-shippable-qr
• windows10-64-2004-qr
• windows10-64-2004-shippable-qr

Comment 11

[Intermittent Failures Robot]

49 failures in 3159 pushes (0.016 failures/push) were associated with this bug in the last 7 days.

This is the #21 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:

• autoland: 34
• mozilla-central: 8
• mozilla-beta: 4
• try: 3

Platform and build breakdown:

• windows10-32-2004-qr: 11
  • opt: 11
• windows10-64-2004-qr: 15
  • opt: 15
• windows10-64-2004-shippable-qr: 10
  • opt: 10
• windows10-64-2004-devedition-qr: 4
  • opt: 4
• windows10-32-2004-shippable-qr: 7
  • opt: 7
• windows10-64-2004-ccov-qr: 1
  • opt: 1
• macosx1015-64-qr: 1
  • debug: 1

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

Comment 12

[Rob Wu [:robwu]]

The test seems to consistently be stuck at test_registerContentScripts_with_wrong_matches, most likely around https://searchfox.org/mozilla-central/rev/2e328e8040a4b4419647aabdc536a3f61bafc384/toolkit/components/extensions/test/mochitest/test_ext_scripting_contentScripts.html#819

Will, could you take a look when you have the chance?

Comment 13

[William Durand [:willdurand]]

Attachment: Bug 1761550 - Remove tab after having unloaded the extensions. r?rpl!

Initially, I thought the bug was related to a missing extension.id in
ExtensionProcessScript.jsm 1 but that isn't always reproducible.

There is possibly an issue there but I don't think it is the root cause
of the intermittent here (I would think that other OSes would be affected,
w hich isn't the case according to 2).

@rpl and I investigated and we noticed that the mochitest error reported
didn't contain a meaningful error:

[object Object] - Should not throw any errors

Once we fixed the test framework output, we got:

FAIL {"operation":"remove","path":"C:\\Users\\William\\AppData\\Local\\Temp\\generated-extension-23.xpi","winLastError":5,"stack":"","fileName":"(unknown module)"} - Should not throw any errors

This is why this patch attempts to fix the intermittent by unloading the
extensions first and then removing the tab. As @rpl said:

That may actually make sense, maybe removing the tab right before the
unload prevented the extension to coordinate with the child process and
make sure we flushed the cache, and that process may not have been yet
fully destroyed.

Comment 14

[William Durand [:willdurand]]

(In reply to William Durand [:willdurand] from comment #13)

Initially, I thought the bug was related to a missing extension.id in
ExtensionProcessScript.jsm [1] but that isn't always reproducible.

About that, this error was thrown while executing test_registerContentScripts_with_wrong_matches on Windows (but not all the time) and the stack trace was:

 0:45.78 GECKO(1624) Console message: [JavaScript Error: "can't access property "id", extension is null" {file: "resource://gre/modules/ExtensionProcessScript.jsm" line: 124}]
 0:45.78 GECKO(1624) initExtensionPolicy@resource://gre/modules/ExtensionProcessScript.jsm:124:18
 0:45.78 GECKO(1624) initExtension@resource://gre/modules/ExtensionProcessScript.jsm:211:23
 0:45.78 GECKO(1624) receiveMessage@resource://gre/modules/ExtensionProcessScript.jsm:229:16
 0:45.78 GECKO(1624) MessageListener.receiveMessage*init@resource://gre/modules/ExtensionProcessScript.jsm:75:19
 0:45.78 GECKO(1624) @resource://gre/modules/ExtensionProcessScript.jsm:472:18
 0:45.78 GECKO(1624) @resource://gre/modules/extensionProcessScriptLoader.js:6:13

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/4a00821f64ad
Remove tab after having unloaded the extensions. r=rpl

Comment 16

[Andreea Pavel [:apavel]]

https://hg.mozilla.org/mozilla-central/rev/4a00821f64ad

Comment 17

[Intermittent Failures Robot]

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

This is the #21 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:

• autoland: 26
• mozilla-release: 1
• mozilla-central: 3
• try: 4

Platform and build breakdown:

• windows10-32-2004-qr: 4
  • opt: 4
• windows10-64-2004-shippable-qr: 11
  • opt: 11
• windows10-64-2004-qr: 14
  • opt: 14
• windows10-32-2004-shippable-qr: 5
  • opt: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1761550&startday=2022-04-25&endday=2022-05-01&tree=all

Comment 18

[Intermittent Failures Robot]

1 failures in 3317 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-release: 1

Platform and build breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1761550&startday=2022-05-09&endday=2022-05-15&tree=all

Comment 19

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-release: 2

Platform and build breakdown:

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

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