Closed Bug 1618059 Opened 5 years ago Closed 5 years ago

Intermittent devtools/server/tests/xpcshell/test_extension_storage_actor.js | xpcshell return code: 0

Categories

(DevTools :: General, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED FIXED

People

(Reporter: intermittent-bug-filer, Assigned: jdescottes)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell disabled])

Attachments

(2 files)

Filed by: ncsoregi [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=290463132&repo=mozilla-beta
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/RH0aire9RG-9l2cr7aGfOg/runs/0/artifacts/public/logs/live_backing.log


[task 2020-02-26T00:18:47.175Z] 00:18:47 INFO - TEST-START | devtools/server/tests/xpcshell/test_extension_storage_actor.js
[task 2020-02-26T00:18:53.304Z] 00:18:53 WARNING - TEST-UNEXPECTED-FAIL | devtools/server/tests/xpcshell/test_extension_storage_actor.js | xpcshell return code: 0
[task 2020-02-26T00:18:53.305Z] 00:18:53 INFO - TEST-INFO took 6125ms
[task 2020-02-26T00:18:53.305Z] 00:18:53 INFO - >>>>>>>
[task 2020-02-26T00:18:53.306Z] 00:18:53 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2020-02-26T00:18:53.306Z] 00:18:53 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2020-02-26T00:18:53.306Z] 00:18:53 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2020-02-26T00:18:53.307Z] 00:18:53 INFO - running event loop
[task 2020-02-26T00:18:53.307Z] 00:18:53 INFO - devtools/server/tests/xpcshell/test_extension_storage_actor.js | Starting setup
[task 2020-02-26T00:18:53.307Z] 00:18:53 INFO - (xpcshell/head.js) | test setup pending (2)
[task 2020-02-26T00:18:53.308Z] 00:18:53 INFO - PID 15888 | 1582676327405 addons.manager DEBUG Application has been upgraded
[task 2020-02-26T00:18:53.308Z] 00:18:53 INFO - PID 15888 | 1582676327406 addons.manager DEBUG Loaded provider scope for resource://gre/modules/addons/XPIProvider.jsm: ["XPIProvider", "XPIInternal"]
[task 2020-02-26T00:18:53.308Z] 00:18:53 INFO - PID 15888 | 1582676327409 addons.manager DEBUG Loaded provider scope for resource://gre/modules/addons/GMPProvider.jsm
[task 2020-02-26T00:18:53.309Z] 00:18:53 INFO - PID 15888 | 1582676327413 addons.manager DEBUG Loaded provider scope for resource://gre/modules/addons/PluginProvider.jsm
[task 2020-02-26T00:18:53.309Z] 00:18:53 INFO - PID 15888 | 1582676327413 addons.manager DEBUG Starting provider: XPIProvider
[task 2020-02-26T00:18:53.309Z] 00:18:53 INFO - PID 15888 | 1582676327413 addons.xpi DEBUG startup
[task 2020-02-26T00:18:53.310Z] 00:18:53 INFO - PID 15888 | 1582676327413 addons.xpi WARN List of valid built-in add-ons could not be parsed.: [Exception... "Component returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsIXPCComponents_Utils.readUTF8URI]" nsresult: "0xc1f30001 (NS_ERROR_NOT_INITIALIZED)" location: "JS frame :: resource://gre/modules/addons/XPIProvider.jsm :: startup :: line 2372" data: no] Stack trace: startup()@resource://gre/modules/addons/XPIProvider.jsm:2372
[task 2020-02-26T00:18:53.310Z] 00:18:53 INFO - PID 15888 | callProvider()@resource://gre/modules/AddonManager.jsm:215
[task 2020-02-26T00:18:53.311Z] 00:18:53 INFO - PID 15888 | _startProvider()@resource://gre/modules/AddonManager.jsm:587
[task 2020-02-26T00:18:53.311Z] 00:18:53 INFO - PID 15888 | startup()@resource://gre/modules/AddonManager.jsm:811
[task 2020-02-26T00:18:53.311Z] 00:18:53 INFO - PID 15888 | startup()@resource://gre/modules/AddonManager.jsm:3482
[task 2020-02-26T00:18:53.312Z] 00:18:53 INFO - PID 15888 | observe()@resource://gre/modules/addonManager.js:87
[task 2020-02-26T00:18:53.312Z] 00:18:53 INFO - PID 15888 | promiseStartupManager()@resource://testing-common/AddonTestUtils.jsm:1003
[task 2020-02-26T00:18:53.313Z] 00:18:53 INFO - PID 15888 | setup()@Z:/task_1582675384/build/tests/xpcshell/tests/devtools/server/tests/xpcshell/test_extension_storage_actor.js:204
[task 2020-02-26T00:18:53.313Z] 00:18:53 INFO - PID 15888 | run_next_test/_run_next_test/<()@Z:\task_1582675384\build\tests\xpcshell\head.js:1567
[task 2020-02-26T00:18:53.314Z] 00:18:53 INFO - PID 15888 | _run_next_test()@Z:\task_1582675384\build\tests\xpcshell\head.js:1567
[task 2020-02-26T00:18:53.314Z] 00:18:53 INFO - PID 15888 | run()@Z:\task_1582675384\build\tests\xpcshell\head.js:735
[task 2020-02-26T00:18:53.314Z] 00:18:53 INFO - PID 15888 | _do_main()@Z:\task_1582675384\build\tests\xpcshell\head.js:246
[task 2020-02-26T00:18:53.315Z] 00:18:53 INFO - PID 15888 | _execute_test()@Z:\task_1582675384\build\tests\xpcshell\head.js:573
[task 2020-02-26T00:18:53.315Z] 00:18:53 INFO - PID 15888 | -e:1

[task 2020-02-26T00:18:53.412Z] 00:18:53 INFO - TEST-PASS | devtools/server/tests/xpcshell/test_extension_storage_actor.js | test_panel_live_updates - [test_panel_live_updates : 458] Got the expected results on populated storage.local - [] deepEqual []
[task 2020-02-26T00:18:53.413Z] 00:18:53 INFO - PID 15888 | console.warn: "Error while detaching the browsing context target front:" (new Error("wrongState", "resource://devtools/shared/protocol/Front.js", 276))
[task 2020-02-26T00:18:53.413Z] 00:18:53 INFO - PID 15888 | 1582676329519 addons.xpi DEBUG Calling bootstrap method shutdown on 0df02dd475392ad4c6e4f7261a5bb299d31c1bf3@temporary-addon version 1.0
[task 2020-02-26T00:18:53.413Z] 00:18:53 INFO - "CONSOLE_MESSAGE: (info) 1582676329519 addons.xpi DEBUG Calling bootstrap method shutdown on 0df02dd475392ad4c6e4f7261a5bb299d31c1bf3@temporary-addon version 1.0"
[task 2020-02-26T00:18:53.414Z] 00:18:53 INFO - PID 15888 | DBG-TEST: head_dbg.js observed a console message: 1582676329519 addons.xpi DEBUG Calling bootstrap method shutdown on 0df02dd475392ad4c6e4f7261a5bb299d31c1bf3@temporary-addon version 1.0
[task 2020-02-26T00:18:53.414Z] 00:18:53 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "sendRemoveListener on closed conduit 0df02dd475392ad4c6e4f7261a5bb299d31c1bf3@temporary-addon.412316860416" {file: "resource://gre/modules/ConduitsChild.jsm" line: 108}]
[task 2020-02-26T00:18:53.414Z] 00:18:53 INFO - _send@resource://gre/modules/ConduitsChild.jsm:108:13
[task 2020-02-26T00:18:53.414Z] 00:18:53 INFO - removeListener@resource://gre/modules/ExtensionChild.jsm:1138:34
[task 2020-02-26T00:18:53.415Z] 00:18:53 INFO - removeListener@resource://gre/modules/ExtensionChild.jsm:1361:40
[task 2020-02-26T00:18:53.415Z] 00:18:53 INFO - getAPI/register/<.storage.onChanged@chrome://extensions/content/child/ext-storage.js:333:22
[task 2020-02-26T00:18:53.415Z] 00:18:53 INFO - removeListener@resource://gre/modules/ExtensionCommon.jsm:2544:7
[task 2020-02-26T00:18:53.415Z] 00:18:53 INFO - revoke@resource://gre/modules/ExtensionCommon.jsm:2566:12
[task 2020-02-26T00:18:53.415Z] 00:18:53 INFO - close@resource://gre/modules/ExtensionCommon.jsm:2571:10
[task 2020-02-26T00:18:53.416Z] 00:18:53 INFO - unload@resource://gre/modules/ExtensionCommon.jsm:910:11
[task 2020-02-26T00:18:53.416Z] 00:18:53 INFO - unload@resource://gre/modules/ExtensionPageChild.jsm:261:11
[task 2020-02-26T00:18:53.416Z] 00:18:53 INFO - unload@resource://gre/modules/ExtensionPageChild.jsm:310:11
[task 2020-02-26T00:18:53.417Z] 00:18:53 INFO - destroyExtensionContext@resource://gre/modules/ExtensionPageChild.jsm:494:15
[task 2020-02-26T00:18:53.417Z] 00:18:53 INFO - observe@resource://gre/modules/ExtensionPageChild.jsm:407:12

See Also: → 1644913

This got frequent, please investigate.

Flags: needinfo?(odvarko)

Julian, you were working on bug 1644913. Is there more we can do here?
Honza

Flags: needinfo?(odvarko) → needinfo?(jdescottes)

The error is different from the one I fixed in Bug 1644913. Also the spike started on June 14th while my fix landed on June 11th, so I don't think there is a direct connection.

I seem to reproduce the failure consistently locally though, so I'll try to bisect & investigate.

Flags: needinfo?(jdescottes)

According to my bisect the spike was caused by https://bugzilla.mozilla.org/show_bug.cgi?id=1583738 and especially the last patch in the queue: https://hg.mozilla.org/mozilla-central/rev/623d3cc37bb4

Something about attaching the webextension target seems to confuse the test.
We could add a test only variant to Descriptor::getTarget, such as getDetachedTarget.
For now I am trying to understand more what causes the failure.

See Also: → 1583738

The failure only occurs locally when I use an attached target for the test_panel_live_reload test function.
And it only happens if we perform the extension.upgrade call during the test.
Most of the time it seems linked to a "frameUpdated" event fired when the webextension is being updated.
But even after commenting out the event, the test remains intermittent (albeit with a much lower frequency)

A first option would be to expose a new API on the webextension descriptor front in order to create
detached targets.

But it seems that isolating the live_reload test in a dedicated file also fixes the intermittent.
It makes the fix a bit obscure, and it probably means we won't look into the issue much further but
I would prefer to avoid test-only APIs in the codebase.

Assignee: nobody → jdescottes
Status: NEW → ASSIGNED

Thanks for working on this Julian!

Honza

Jan, this bug is on our disable-recommended filter. Could we land the patch after it is reviewed?

Flags: needinfo?(odvarko)

Razvan, yes, it's ok to land your patch and disable the test.
Thanks for the help here!

Flags: needinfo?(odvarko)
Keywords: leave-open
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Pushed by rmaries@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/5dd8b5f7e90f Disabled test_extension_storage_actor.js on Windows. r=jmaher
See Also: → 1650139
Pushed by jdescottes@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/4fa79b8f6fa9 Extract the storage extension live reload test r=ochameau,davidwalsh
Pushed by ncsoregi@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/8e8ac71c572a Add test_extension_storage_actor_upgrade.js to the rejected-words exclude list. a=lint-fix CLOSED TREE
Regressions: 1650221
See Also: → 1620767

Should be fixed now.

Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Keywords: leave-open
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: