1650221 - Intermittent HighFreq devtools/server/tests/xpcshell/test_extension_storage_actor_upgrade.js | test_panel_live_reload - [test_panel_live_reload : 110] Got the expected results on populated storage.local after xpcshell return code: 0

Status: RESOLVED FIXED

(DevTools :: General, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: nbeleuzu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=308363390&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/YpnDuC2JTPyvEhzlmqPsvQ/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/YpnDuC2JTPyvEhzlmqPsvQ/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

[task 2020-07-02T18:20:14.291Z] 18:20:14 INFO - TEST-START | devtools/server/tests/xpcshell/test_extension_storage_actor_upgrade.js
[task 2020-07-02T18:20:15.657Z] 18:20:15 WARNING - TEST-UNEXPECTED-FAIL | devtools/server/tests/xpcshell/test_extension_storage_actor_upgrade.js | xpcshell return code: 0
[task 2020-07-02T18:20:15.659Z] 18:20:15 INFO - TEST-INFO took 1362ms
[task 2020-07-02T18:20:15.659Z] 18:20:15 INFO - >>>>>>>
[task 2020-07-02T18:20:15.659Z] 18:20:15 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2020-07-02T18:20:15.659Z] 18:20:15 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2020-07-02T18:20:15.659Z] 18:20:15 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2020-07-02T18:20:15.659Z] 18:20:15 INFO - running event loop
[task 2020-07-02T18:20:15.660Z] 18:20:15 INFO - devtools/server/tests/xpcshell/test_extension_storage_actor_upgrade.js | Starting setup
[task 2020-07-02T18:20:15.660Z] 18:20:15 INFO - (xpcshell/head.js) | test setup pending (2)
[task 2020-07-02T18:20:15.660Z] 18:20:15 INFO - PID 1393 | DBG-TEST: head_dbg.js observed a console message: 1593714014449 addons.manager DEBUG Application has been upgraded
[task 2020-07-02T18:20:15.660Z] 18:20:15 INFO - "CONSOLE_MESSAGE: (info) 1593714014449 addons.manager DEBUG Application has been upgraded"
[task 2020-07-02T18:20:15.660Z] 18:20:15 INFO - PID 1393 | DBG-TEST: head_dbg.js observed a console message: 1593714014449 addons.manager DEBUG Loaded provider scope for resource://gre/modules/addons/XPIProvider.jsm: ["XPIProvider", "XPIInternal"]
[task 2020-07-02T18:20:15.660Z] 18:20:15 INFO - "CONSOLE_MESSAGE: (info) 1593714014449 addons.manager DEBUG Loaded provider scope for resource://gre/modules/addons/XPIProvider.jsm: ["XPIProvider", "XPIInternal"]"
[task 2020-07-02T18:20:15.660Z] 18:20:15 INFO - PID 1393 | DBG-TEST: head_dbg.js observed a console message: 1593714014453 addons.manager DEBUG Loaded provider scope for resource://gre/modules/addons/GMPProvider.jsm
[task 2020-07-02T18:20:15.660Z] 18:20:15 INFO - "CONSOLE_MESSAGE: (info) 1593714014453 addons.manager DEBUG Loaded provider scope for resource://gre/modules/addons/GMPProvider.jsm"
[task 2020-07-02T18:20:15.660Z] 18:20:15 INFO - PID 1393 | DBG-TEST: head_dbg.js observed a console message: 1593714014454 addons.manager DEBUG Loaded provider scope for resource://gre/modules/addons/PluginProvider.jsm
[task 2020-07-02T18:20:15.660Z] 18:20:15 INFO - "CONSOLE_MESSAGE: (info) 1593714014454 addons.manager DEBUG Loaded provider scope for resource://gre/modules/addons/PluginProvider.jsm"
[task 2020-07-02T18:20:15.661Z] 18:20:15 INFO - PID 1393 | DBG-TEST: head_dbg.js observed a console message: 1593714014454 addons.manager DEBUG Starting provider: XPIProvider
[task 2020-07-02T18:20:15.661Z] 18:20:15 INFO - "CONSOLE_MESSAGE: (info) 1593714014454 addons.manager DEBUG Starting provider: XPIProvider"
[task 2020-07-02T18:20:15.661Z] 18:20:15 INFO - PID 1393 | DBG-TEST: head_dbg.js observed a console message: 1593714014454 addons.xpi DEBUG startup
[task 2020-07-02T18:20:15.661Z] 18:20:15 INFO - "CONSOLE_MESSAGE: (info) 1593714014454 addons.xpi DEBUG startup"
[task 2020-07-02T18:20:15.661Z] 18:20:15 INFO - PID 1393 | DBG-TEST: head_dbg.js observed a console message: 1593714014455 addons.xpi INFO SystemAddonLocation directory is missing
[task 2020-07-02T18:20:15.661Z] 18:20:15 INFO - "CONSOLE_MESSAGE: (info) 1593714014455 addons.xpi INFO SystemAddonLocation directory is missing"
[task 2020-07-02T18:20:15.661Z] 18:20:15 INFO - PID 1393 | DBG-TEST: head_dbg.js observed a console message: 1593714014463 addons.xpi INFO Removing all system add-on upgrades.
[task 2020-07-02T18:20:15.662Z] 18:20:15 INFO - "CONSOLE_MESSAGE: (info) 1593714014463 addons.xpi INFO Removing all system add-on upgrades."
[task 2020-07-02T18:20:15.662Z] 18:20:15 INFO - PID 1393 | DBG-TEST: head_dbg.js observed a console message: 1593714014464 addons.xpi DEBUG checkForChanges
[task 2020-07-02T18:20:15.662Z] 18:20:15 INFO - "CONSOLE_MESSAGE: (info) 1593714014464 addons.xpi DEBUG checkForChanges"
[task 2020-07-02T18:20:15.662Z] 18:20:15 INFO - PID 1393 | DBG-TEST: head_dbg.js observed a console message: 1593714014464 addons.xpi DEBUG Loaded add-on state: ${}
[task 2020-07-02T18:20:15.662Z] 18:20:15 INFO - "CONSOLE_MESSAGE: (info) 1593714014464 addons.xpi DEBUG Loaded add-on state: ${}"
[task 2020-07-02T18:20:15.662Z] 18:20:15 INFO - PID 1393 | DBG-TEST: head_dbg.js observed a console message: 1593714014464 addons.xpi DEBUG scanForChanges changed: false, state: {}
[task 2020-07-02T18:20:15.662Z] 18:20:15 INFO - "CONSOLE_MESSAGE: (info) 1593714014464 addons.xpi DEBUG scanForChanges changed: false, state: {}"
[task 2020-07-02T18:20:15.662Z] 18:20:15 INFO - PID 1393 | DBG-TEST: head_dbg.js observed a console message: 1593714014465 addons.xpi DEBUG Empty XPI database, setting schema version preference to 32
[task 2020-07-02T18:20:15.662Z] 18:20:15 INFO - "CONSOLE_MESSAGE: (info) 1593714014465 addons.xpi DEBUG Empty XPI database, setting schema version preference to 32"
[task 2020-07-02T18:20:15.662Z] 18:20:15 INFO - PID 1393 | DBG-TEST: head_dbg.js observed a console message: 1593714014465 addons.xpi DEBUG No changes found
[task 2020-07-02T18:20:15.662Z] 18:20:15 INFO - "CONSOLE_MESSAGE: (info) 1593714014465 addons.xpi DEBUG No changes found"
[task 2020-07-02T18:20:15.665Z] 18:20:15 INFO - PID 1393 | DBG-TEST: head_dbg.js observed a console message: 1593714014473 addons.xpi-utils DEBUG Synchronously loading the add-ons database
[task 2020-07-02T18:20:15.665Z] 18:20:15 INFO - "CONSOLE_MESSAGE: (info) 1593714014473 addons.xpi-utils DEBUG Synchronously loading the add-ons database"
[task 2020-07-02T18:20:15.665Z] 18:20:15 INFO - PID 1393 | DBG-TEST: head_dbg.js observed a console message: 1593714014473 addons.xpi-utils DEBUG Starting async load of XPI database /tmp/xpc-profile-ENGBVc/extensions.json
[task 2020-07-02T18:20:15.666Z] 18:20:15 INFO - "CONSOLE_MESSAGE: (info) 1593714014473 addons.xpi-utils DEBUG Starting async load of XPI database /tmp/xpc-profile-ENGBVc/extensions.json"
[task 2020-07-02T18:20:15.666Z] 18:20:15 INFO - (xpcshell/head.js) | test run_next_test 0 finished (2)

Comment 1

[Julian Descottes [:jdescottes]]

Interesting, locally running it in a separate test completely fixed the issue, but I guess that either in test-verify or in a suite, we go back to the same issue :( Not sure why it's even more visible than before, now failing on all platforms.

I'll try a few other things, but we might have to add a test-only API to avoid attaching to the target here...
On the plus side, if we skip only this test, we would still run test_extension_storage_actor.js which contains has most of the test coverage.

Comment 2

[Julian Descottes [:jdescottes]]

Something must have landed between the time I created my initial patch and when I landed it, because I pulled https://treeherder.mozilla.org/#/jobs?repo=try&revision=accab5fbdd810ac741767d835d7a461bd27e8653 and the test runs fine with --verify, whereas locally on central it fails super quickly.

Comment 3

[Julian Descottes [:jdescottes]]

Attachment: Bug 1650221 - Wait until storage is ready after extension upgrade in test_extension_storage_actor_upgrade.js

Comment 4

[Intermittent Failures Robot]

19 failures in 692 pushes (0.027 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 14
• mozilla-central: 3
• try: 2

Platform breakdown:

• windows10-64-shippable: 12
• linux1804-64: 1
• linux1804-64-shippable: 1
• linux1804-64-shippable-qr: 3
• windows7-32-shippable: 1
• windows10-64: 1

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

Comment 5

[Intermittent Failures Robot]

56 failures in 4516 pushes (0.012 failures/push) were associated with this bug in the last 7 days.

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

Platform breakdown:

• macosx1014-64: 2
• windows7-32-shippable: 3
• windows10-64-shippable: 31
• linux1804-64-shippable: 8
• macosx1014-64-shippable: 1
• linux1804-64: 1
• linux1804-64-shippable-qr: 4
• windows10-64: 1
• windows7-32-devedition: 2
• windows10-64-devedition: 2
• windows7-32: 1

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

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/0b86e94ad06f
Wait until storage is ready after extension upgrade in test_extension_storage_actor_upgrade.js r=Honza

Comment 7

[Andreea Pavel [:apavel]]

https://hg.mozilla.org/mozilla-central/rev/0b86e94ad06f

Comment 8

[Intermittent Failures Robot]

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

Repository breakdown:

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

Platform breakdown:

• windows10-64-shippable: 2
• linux1804-64-shippable: 2
• linux1804-64-shippable-qr: 2
• linux1804-64: 1

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