1624235 - Intermittent toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js | - A promise chain failed to handle a rejection: Unable to arm timer, the object has been finalized. - stack: arm@resource://gre/modules/DeferredTask.jsm:215:13

Status: RESOLVED FIXED

(WebExtensions :: General, defect, P1)

Description

[Treeherder Bug Filer]

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

---

[task 2020-03-22T22:25:14.886Z] 22:25:14 INFO - TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js | - Got expected manifest name - "en-US 1.1" == "en-US 1.1"
[task 2020-03-22T22:25:14.886Z] 22:25:14 INFO - (xpcshell/head.js) | test run_next_test 2 pending (2)
[task 2020-03-22T22:25:14.886Z] 22:25:14 INFO - (xpcshell/head.js) | test finished (2)
[task 2020-03-22T22:25:14.886Z] 22:25:14 INFO - (xpcshell/head.js) | test run_next_test 2 finished (1)
[task 2020-03-22T22:25:14.886Z] 22:25:14 INFO - exiting test
[task 2020-03-22T22:25:14.887Z] 22:25:14 WARNING - TEST-UNEXPECTED-FAIL | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_startup_cache.js | - A promise chain failed to handle a rejection: Unable to arm timer, the object has been finalized. - stack: arm@resource://gre/modules/DeferredTask.jsm:215:13
[task 2020-03-22T22:25:14.887Z] 22:25:14 INFO - saveSoon@resource://gre/modules/JSONFile.jsm:307:24
[task 2020-03-22T22:25:14.887Z] 22:25:14 INFO - save@resource://gre/modules/addons/XPIProvider.jsm:1603:20
[task 2020-03-22T22:25:14.887Z] 22:25:14 INFO - setStartupData@resource://gre/modules/addons/XPIProvider.jsm:3039:15
[task 2020-03-22T22:25:14.887Z] 22:25:14 INFO - saveStartupData@resource://gre/modules/Extension.jsm:2007:17
[task 2020-03-22T22:25:14.887Z] 22:25:14 INFO - _writePersistentListeners@resource://gre/modules/ExtensionCommon.jsm:2271:15
[task 2020-03-22T22:25:14.887Z] 22:25:14 INFO - savePersistentListener@resource://gre/modules/ExtensionCommon.jsm:2389:18
[task 2020-03-22T22:25:14.887Z] 22:25:14 INFO - addMessagingListener@chrome://extensions/content/parent/ext-runtime.js:196:42
[task 2020-03-22T22:25:14.887Z] 22:25:14 INFO - recvAPICall/result</<@resource://gre/modules/ExtensionParent.jsm:960:68
[task 2020-03-22T22:25:14.887Z] 22:25:14 INFO - withPendingBrowser@resource://gre/modules/ExtensionParent.jsm:592:26
[task 2020-03-22T22:25:14.887Z] 22:25:14 INFO - recvAPICall/result<@resource://gre/modules/ExtensionParent.jsm:960:24
[task 2020-03-22T22:25:14.887Z] 22:25:14 INFO - callAndLog@resource://gre/modules/ExtensionParent.jsm:922:14
[task 2020-03-22T22:25:14.887Z] 22:25:14 INFO - recvAPICall@resource://gre/modules/ExtensionParent.jsm:959:25
[task 2020-03-22T22:25:14.887Z] 22:25:14 INFO - Async*_recv@resource://gre/modules/ConduitsChild.jsm:78:20
[task 2020-03-22T22:25:14.887Z] 22:25:14 INFO - receiveMessage@resource://gre/modules/ConduitsParent.jsm:333:20
[task 2020-03-22T22:25:14.887Z] 22:25:14 INFO - _do_main@Z:\task_1584914388\build\tests\xpcshell\head.js:246:6
[task 2020-03-22T22:25:14.887Z] 22:25:14 INFO - _execute_test@Z:\task_1584914388\build\tests\xpcshell\head.js:573:5
[task 2020-03-22T22:25:14.887Z] 22:25:14 INFO - @-e:1:1
[task 2020-03-22T22:25:14.887Z] 22:25:14 INFO - Rejection date: Sun Mar 22 2020 22:25:14 GMT+0000 (Greenwich Mean Time) - false == true
[task 2020-03-22T22:25:14.888Z] 22:25:14 INFO - resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:265
[task 2020-03-22T22:25:14.888Z] 22:25:14 INFO - Z:\task_1584914388\build\tests\xpcshell\head.js:_execute_test:574
[task 2020-03-22T22:25:14.888Z] 22:25:14 INFO - -e:null:1
[task 2020-03-22T22:25:14.888Z] 22:25:14 INFO - exiting test

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows7-32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1624235&startday=2020-03-16&endday=2020-03-22&tree=all

Comment 2

[Cristina Coroiu [:ccoroiu]]

Started retriggers:
https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=linux64-tsan%2Copt%2CXpcshell%2Ctests%2Ctest-linux64-tsan%2Fopt-xpcshell-e10s-1%2CX%28X1%29&tochange=310fe319cb3d8deb106acb5e6361b0c86111dfd0&fromchange=437249143591b1e434b2a02a24734abd6f66630a&selectedJob=294804858

Comment 3

[Intermittent Failures Robot]

40 failures in 4773 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

This is the #27 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
• mozilla-central: 8
• try: 3

Platform breakdown:

• linux64-tsan: 21
• windows10-64-shippable: 8
• windows7-32: 3
• windows10-64-devedition: 1
• windows10-64: 2
• linux1804-64-tsan: 4
• macosx1014-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1624235&startday=2020-03-23&endday=2020-03-29&tree=all

Comment 4

[Bogdan Tara[:bogdan_tara | bogdant]]

Could these be caused by the changes on bug 1624267?
decoder could you, please take a look?

Comment 5

[Intermittent Failures Robot]

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

This is the #43 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: 25
• try: 1
• mozilla-central: 6

Platform breakdown:

• windows10-64-shippable: 8
• windows7-32: 3
• windows10-64: 1
• macosx1014-64-shippable: 9
• linux1804-64-tsan: 10
• windows7-32-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1624235&startday=2020-03-30&endday=2020-04-05&tree=all

Comment 6

[Shane Caraveo (:mixedpuppy)]

Given this happens on all platforms, I don't think it would be bug 1624267.

The traceback indicates that an event following the browser.test.onMessage call in the test file has somehow been delayed past the extension unload AND the addon manager shutdown. The JSONFile saver is finalized during the addon manager shutdown, and would produce the error only after that.

Given this is going through conduits, maybe Tom has an idea why (or whether) an event is somehow becoming very delayed.

Comment 7

[Shane Caraveo (:mixedpuppy)]

I've a perma-fail repro for this now.

Comment 8

[Shane Caraveo (:mixedpuppy)]

the NativeMessenger constructor[1] making a call to the parent. that does a conduit.sendAPICall[2]. The test finishes, we shutdown the addonmanager, then the parent side receives that call and tries to persist the event listener[3]. The is easily reproducible running the in-process tests, and reproducible running remote test with --verify.

I have yet to figure out a solid fix for this. Some minor changes in the test make it less likely to happen, but doesn't fix it.

[1] https://searchfox.org/mozilla-central/rev/4e228dc5f594340d35da7453829ad9f3c3cb8b58/toolkit/components/extensions/ExtensionChild.jsm#266
[2] https://searchfox.org/mozilla-central/rev/4e228dc5f594340d35da7453829ad9f3c3cb8b58/toolkit/components/extensions/ExtensionChild.jsm#951
[3] https://searchfox.org/mozilla-central/rev/4e228dc5f594340d35da7453829ad9f3c3cb8b58/toolkit/components/extensions/parent/ext-runtime.js#196

Comment 9

[Shane Caraveo (:mixedpuppy)]

I've disabled test_ext_startupData.js in bug 1628307 in order to get our tests running correctly again for in-process tests.

That test fails due to the NativeMessenger constructor change from bug 1316748, however, removing that api call there results in failures in test_ext_messaging_startup.js.

Tom, any thoughts on how to address this? Essentially that call results in the runtime namespace being loaded[1]. However, that load races with the test itself, and looses.

[1] https://searchfox.org/mozilla-central/rev/4e228dc5f594340d35da7453829ad9f3c3cb8b58/toolkit/components/extensions/ExtensionParent.jsm#958

Comment 10

[Shane Caraveo (:mixedpuppy)]

BTW, simply adding an empty runtime.onConnect listener to the background script is enough to fix this test file, but I'd like a second opinion on whether this is going to be an ongoing issue in other tests as well, or if there is a way to fix the underlying issue.

Comment 11

[Tomislav Jovanovic :zombie]

The runtime.addMessagingListener is a bit of hack already, it doesn't actually setup persisted event listeners, but instead sets up [1] a way for ExtensionParent.jsm to wakeup the background page [2] when it gets a message:

https://searchfox.org/mozilla-central/rev/4e228dc5/toolkit/components/extensions/parent/ext-runtime.js#235
https://searchfox.org/mozilla-central/rev/4e228dc5/toolkit/components/extensions/ExtensionParent.jsm#296

I think we can just simplify this by removing addMessagingListener altogether and always setting up wakeupBackground (but not actually calling it until needed).

Comment 12

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1
• autoland: 18
• try: 2

Platform breakdown:

• linux1804-64-tsan: 12
• macosx1014-64-shippable: 7
• windows10-64-shippable: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1624235&startday=2020-04-06&endday=2020-04-12&tree=all

Comment 13

[Tomislav Jovanovic :zombie]

Attachment: Bug 1624235 - Simplify handling of persistent listeners for runtime messaging

Also, unconfuse two different meaning of the "startup" event.
Bonus, shut up some logspam during tests.

Comment 15

[Intermittent Failures Robot]

39 failures in 4528 pushes (0.009 failures/push) were associated with this bug in the last 7 days.

This is the #42 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: 5
• mozilla-beta: 2
• try: 4

Platform breakdown:

• windows10-64: 1
• linux1804-64-tsan: 17
• windows10-64-shippable: 9
• macosx1014-64-shippable: 7
• linux1804-64-shippable-qr: 1
• windows10-64-devedition: 3
• windows7-32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1624235&startday=2020-04-13&endday=2020-04-19&tree=all

Comment 16

[Intermittent Failures Robot]

15 failures in 955 pushes (0.016 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 12
• mozilla-central: 2
• try: 1

Platform breakdown:

• windows10-64-shippable: 3
• linux1804-64-tsan: 8
• windows7-32: 1
• macosx1014-64-shippable: 2
• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1624235&startday=2020-04-20&endday=2020-04-20&tree=all

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/7f4f1d605c69
Simplify handling of persistent listeners for runtime messaging r=robwu

Comment 18

[Stefan Hindli [:stefan_hindli]]

Over the last 7 days there are 39 failures on this bug. These happen on: linux1804-64-tsan, macosx1014-64-shippable, windows10-64, windows10-64-shippable, windows7-32, windows7-32-shippable
here is the most recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=298904856&repo=autoland&lineNumber=2923

Comment 19

[Noemi Erli[:noemi_erli]]

https://hg.mozilla.org/mozilla-central/rev/7f4f1d605c69

Comment 20

[Intermittent Failures Robot]

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

** 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-central: 2
• try: 1
• mozilla-beta: 2

Platform breakdown:

• linux1804-64-tsan: 16
• windows10-64-shippable: 7
• windows7-32: 1
• macosx1014-64-shippable: 4
• windows10-64: 2
• windows7-32-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1624235&startday=2020-04-20&endday=2020-04-26&tree=all