1620767 - Intermittent devtools/server/tests/xpcshell/test_extension_storage_actor.js | test_panel_live_reload - [test_panel_live_reload : 1036] Got the expected results on populated storage.local - [] deepEqual [{"area":"local","name":"a","value":{"str":"123"}

Status: RESOLVED FIXED

(DevTools :: General, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-03-07T12:27:12.172Z] 12:27:12 INFO - "CONSOLE_MESSAGE: (info) 1583584031664 addons.xpi-utils DEBUG Make addon app-temporary:[e-mail] visible"
[task 2020-03-07T12:27:12.172Z] 12:27:12 INFO - PID 12652 | DBG-TEST: head_dbg.js observed a console message: 1583584031664 addons.xpi DEBUG Updating XPIState for {"id":"[e-mail]","syncGUID":"{755cc6c5-37b9-4315-9461-4ba9d98b0486}","version":"2.0","type":"extension","loader":null,"updateURL":null,"optionsURL":null,"optionsType":null,"optionsBrowserStyle":true,"aboutURL":null,"defaultLocale":{"name":"Generated extension","creator":null,"developers":null,"translators":null,"contributors":null},"visible":true,"active":true,"userDisabled":false,"appDisabled":false,"embedderDisabled":false,"installDate":1583584031328,"applyBackgroundUpdates":1,"path":"c:\\users\\task_1583582905\\appdata\\local\\temp\\xpc-profile-ehyn7j\\tmp\\generated-extension-1.xpi","skinnable":false,"sourceURI":null,"releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"strictCompatibility":true,"locales":[],"targetApplications":[{"id":"[e-mail]","minVersion":null,"maxVersion":null}],"targetPlatforms":[],"signedState":0,"seen":true,"dependencies":[],"incognito":"spanning","userPermissions":{"permissions":["storage"],"origins":[]},"icons":{},"iconURL":null,"blocklistState":0,"blocklistURL":null,"startupData":null,"hidden":false,"installTelemetryInfo":null,"recommendationState":null,"rootURI":"jar:file:///c:/users/task_1583582905/appdata/local/temp/xpc-profile-ehyn7j/tmp/generated-extension-1.xpi!/","location":"app-temporary"}
[task 2020-03-07T12:27:12.172Z] 12:27:12 INFO - "CONSOLE_MESSAGE: (info) 1583584031664 addons.xpi DEBUG Updating XPIState for {"id":"[e-mail]","syncGUID":"{755cc6c5-37b9-4315-9461-4ba9d98b0486}","version":"2.0","type":"extension","loader":null,"updateURL":null,"optionsURL":null,"optionsType":null,"optionsBrowserStyle":true,"aboutURL":null,"defaultLocale":{"name":"Generated extension","creator":null,"developers":null,"translators":null,"contributors":null},"visible":true,"active":true,"userDisabled":false,"appDisabled":false,"embedderDisabled":false,"installDate":1583584031328,"applyBackgroundUpdates":1,"path":"c:\\users\\task_1583582905\\appdata\\local\\temp\\xpc-profile-ehyn7j\\tmp\\generated-extension-1.xpi","skinnable":false,"sourceURI":null,"releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"strictCompatibility":true,"locales":[],"targetApplications":[{"id":"[e-mail]","minVersion":null,"maxVersion":null}],"targetPlatforms":[],"signedState":0,"seen":true,"dependencies":[],"incognito":"spanning","userPermissions":{"permissions":["storage"],"origins":[]},"icons":{},"iconURL":null,"blocklistState":0,"blocklistURL":null,"startupData":null,"hidden":false,"installTelemetryInfo":null,"recommendationState":null,"rootURI":"jar:file:///c:/users/task_1583582905/appdata/local/temp/xpc-profile-ehyn7j/tmp/generated-extension-1.xpi!/","location":"app-temporary"}"
[task 2020-03-07T12:27:12.172Z] 12:27:12 INFO - PID 12652 | DBG-TEST: head_dbg.js observed a console message: 1583584031664 addons.xpi DEBUG XPIStates adding add-on [e-mail] in {}: c:\users\task_1583582905\appdata\local\temp\xpc-profile-ehyn7j\tmp\generated-extension-1.xpi
[task 2020-03-07T12:27:12.172Z] 12:27:12 INFO - "CONSOLE_MESSAGE: (info) 1583584031664 addons.xpi DEBUG XPIStates adding add-on [e-mail] in {}: c:\users\task_1583582905\appdata\local\temp\xpc-profile-ehyn7j\tmp\generated-extension-1.xpi"
[task 2020-03-07T12:27:12.172Z] 12:27:12 INFO - PID 12652 | DBG-TEST: head_dbg.js observed a console message: 1583584031664 addons.xpi DEBUG Updating XPIState for {"id":"[e-mail]","syncGUID":"{755cc6c5-37b9-4315-9461-4ba9d98b0486}","version":"2.0","type":"extension","loader":null,"updateURL":null,"optionsURL":null,"optionsType":null,"optionsBrowserStyle":true,"aboutURL":null,"defaultLocale":{"name":"Generated extension","creator":null,"developers":null,"translators":null,"contributors":null},"visible":true,"active":true,"userDisabled":false,"appDisabled":false,"embedderDisabled":false,"installDate":1583584031328,"applyBackgroundUpdates":1,"path":"c:\\users\\task_1583582905\\appdata\\local\\temp\\xpc-profile-ehyn7j\\tmp\\generated-extension-1.xpi","skinnable":false,"sourceURI":null,"releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"strictCompatibility":true,"locales":[],"targetApplications":[{"id":"[e-mail]","minVersion":null,"maxVersion":null}],"targetPlatforms":[],"signedState":0,"seen":true,"dependencies":[],"incognito":"spanning","userPermissions":{"permissions":["storage"],"origins":[]},"icons":{},"iconURL":null,"blocklistState":0,"blocklistURL":null,"startupData":null,"hidden":false,"installTelemetryInfo":null,"recommendationState":null,"rootURI":"jar:file:///c:/users/task_1583582905/appdata/local/temp/xpc-profile-ehyn7j/tmp/generated-extension-1.xpi!/","location":"app-temporary"}
[task 2020-03-07T12:27:12.172Z] 12:27:12 INFO - "CONSOLE_MESSAGE: (info) 1583584031664 addons.xpi DEBUG Updating XPIState for {"id":"[e-mail]","syncGUID":"{755cc6c5-37b9-4315-9461-4ba9d98b0486}","version":"2.0","type":"extension","loader":null,"updateURL":null,"optionsURL":null,"optionsType":null,"optionsBrowserStyle":true,"aboutURL":null,"defaultLocale":{"name":"Generated extension","creator":null,"developers":null,"translators":null,"contributors":null},"visible":true,"active":true,"userDisabled":false,"appDisabled":false,"embedderDisabled":false,"installDate":1583584031328,"applyBackgroundUpdates":1,"path":"c:\\users\\task_1583582905\\appdata\\local\\temp\\xpc-profile-ehyn7j\\tmp\\generated-extension-1.xpi","skinnable":false,"sourceURI":null,"releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"strictCompatibility":true,"locales":[],"targetApplications":[{"id":"[e-mail]","minVersion":null,"maxVersion":null}],"targetPlatforms":[],"signedState":0,"seen":true,"dependencies":[],"incognito":"spanning","userPermissions":{"permissions":["storage"],"origins":[]},"icons":{},"iconURL":null,"blocklistState":0,"blocklistURL":null,"startupData":null,"hidden":false,"installTelemetryInfo":null,"recommendationState":null,"rootURI":"jar:file:///c:/users/task_1583582905/appdata/local/temp/xpc-profile-ehyn7j/tmp/generated-extension-1.xpi!/","location":"app-temporary"}"
[task 2020-03-07T12:27:12.172Z] 12:27:12 INFO - PID 12652 | DBG-TEST: head_dbg.js observed a console message: 1583584031665 addons.xpi DEBUG Loading bootstrap scope from jar:file:///c:/users/task_1583582905/appdata/local/temp/xpc-profile-ehyn7j/tmp/generated-extension-1.xpi!/
[task 2020-03-07T12:27:12.173Z] 12:27:12 INFO - "CONSOLE_MESSAGE: (info) 1583584031665 addons.xpi DEBUG Loading bootstrap scope from jar:file:///c:/users/task_1583582905/appdata/local/temp/xpc-profile-ehyn7j/tmp/generated-extension-1.xpi!/"
[task 2020-03-07T12:27:12.173Z] 12:27:12 INFO - PID 12652 | DBG-TEST: head_dbg.js observed a console message: 1583584031665 addons.xpi DEBUG Calling bootstrap method update on [e-mail] version 2.0
[task 2020-03-07T12:27:12.173Z] 12:27:12 INFO - "CONSOLE_MESSAGE: (info) 1583584031665 addons.xpi DEBUG Calling bootstrap method update on [e-mail] version 2.0"
[task 2020-03-07T12:27:12.173Z] 12:27:12 INFO - PID 12652 | DBG-TEST: resource://gre/modules/ConduitsChild.jsm:108: error: sendRemoveListener on closed conduit [e-mail].1786706395136
[task 2020-03-07T12:27:12.173Z] 12:27:12 INFO - PID 12652 | DBG-TEST: head_dbg.js observed a console message: sendRemoveListener on closed conduit [e-mail].1786706395136
[task 2020-03-07T12:27:12.173Z] 12:27:12 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "sendRemoveListener on closed conduit [e-mail].1786706395136" {file: "resource://gre/modules/ConduitsChild.jsm" line: 108}]
[task 2020-03-07T12:27:12.173Z] 12:27:12 INFO - _send@resource://gre/modules/ConduitsChild.jsm:108:13
[task 2020-03-07T12:27:12.173Z] 12:27:12 INFO - removeListener@resource://gre/modules/ExtensionChild.jsm:1138:34
[task 2020-03-07T12:27:12.173Z] 12:27:12 INFO - removeListener@resource://gre/modules/ExtensionChild.jsm:1361:40
[task 2020-03-07T12:27:12.173Z] 12:27:12 INFO - getAPI/register/<.storage.onChanged@chrome://extensions/content/child/ext-storage.js:333:22
[task 2020-03-07T12:27:12.173Z] 12:27:12 INFO - removeListener@resource://gre/modules/ExtensionCommon.jsm:2544:7
[task 2020-03-07T12:27:12.173Z] 12:27:12 INFO - revoke@resource://gre/modules/ExtensionCommon.jsm:2566:12
[task 2020-03-07T12:27:12.174Z] 12:27:12 INFO - close@resource://gre/modules/ExtensionCommon.jsm:2571:10
[task 2020-03-07T12:27:12.174Z] 12:27:12 INFO - unload@resource://gre/modules/ExtensionCommon.jsm:910:11
[task 2020-03-07T12:27:12.174Z] 12:27:12 INFO - unload@resource://gre/modules/ExtensionPageChild.jsm:261:11
[task 2020-03-07T12:27:12.174Z] 12:27:12 INFO - unload@resource://gre/modules/ExtensionPageChild.jsm:310:11
[task 2020-03-07T12:27:12.174Z] 12:27:12 INFO - destroyExtensionContext@resource://gre/modules/ExtensionPageChild.jsm:494:15
[task 2020-03-07T12:27:12.174Z] 12:27:12 INFO - observe@resource://gre/modules/ExtensionPageChild.jsm:407:12
[task 2020-03-07T12:27:12.174Z] 12:27:12 INFO - "
[task 2020-03-07T12:27:12.174Z] 12:27:12 INFO - PID 12652 | 1583584031668 addons.xpi DEBUG Calling bootstrap method startup on [e-mail] version 2.0
[task 2020-03-07T12:27:12.174Z] 12:27:12 INFO - PID 12652 | DBG-TEST: head_dbg.js observed a console message: 1583584031668 addons.xpi DEBUG Calling bootstrap method startup on [e-mail] version 2.0
[task 2020-03-07T12:27:12.174Z] 12:27:12 INFO - "CONSOLE_MESSAGE: (info) 1583584031668 addons.xpi DEBUG Calling bootstrap method startup on [e-mail] version 2.0"
[task 2020-03-07T12:27:12.175Z] 12:27:12 INFO - "Extension attached"
[task 2020-03-07T12:27:12.175Z] 12:27:12 INFO - PID 12652 | JavaScript error: resource://devtools/server/actors/targets/browsing-context.js, line 371: NS_ERROR_NOT_AVAILABLE: Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIDocShell.domWindow]
[task 2020-03-07T12:27:12.175Z] 12:27:12 INFO - PID 12652 | DBG-TEST: resource://devtools/server/actors/targets/browsing-context.js:371: exception: NS_ERROR_NOT_AVAILABLE: Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIDocShell.domWindow]
[task 2020-03-07T12:27:12.175Z] 12:27:12 INFO - PID 12652 | DBG-TEST: head_dbg.js observed a console message: NS_ERROR_NOT_AVAILABLE: Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIDocShell.domWindow]
[task 2020-03-07T12:27:12.175Z] 12:27:12 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "NS_ERROR_NOT_AVAILABLE: Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIDocShell.domWindow]" {file: "resource://devtools/server/actors/targets/browsing-context.js" line: 371}]"
[task 2020-03-07T12:27:12.175Z] 12:27:12 INFO - PID 12652 | 1583584031704 addons.xpi DEBUG Install of temporary addon in c:\users\task_1583582905\appdata\local\temp\xpc-profile-ehyn7j\tmp\generated-extension-1.xpi completed.
[task 2020-03-07T12:27:12.175Z] 12:27:12 INFO - PID 12652 | DBG-TEST: head_dbg.js observed a console message: 1583584031704 addons.xpi DEBUG Install of temporary addon in c:\users\task_1583582905\appdata\local\temp\xpc-profile-ehyn7j\tmp\generated-extension-1.xpi completed.
[task 2020-03-07T12:27:12.175Z] 12:27:12 INFO - "CONSOLE_MESSAGE: (info) 1583584031704 addons.xpi DEBUG Install of temporary addon in c:\users\task_1583582905\appdata\local\temp\xpc-profile-ehyn7j\tmp\generated-extension-1.xpi completed."
[task 2020-03-07T12:27:12.175Z] 12:27:12 WARNING - TEST-UNEXPECTED-FAIL | devtools/server/tests/xpcshell/test_extension_storage_actor.js | test_panel_live_reload - [test_panel_live_reload : 1036] Got the expected results on populated storage.local - [] deepEqual [{"area":"local","name":"a","value":{"str":"123"},"isValueEditable":true}]

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 2

Platform breakdown:

• windows10-64-shippable: 2

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

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• linux1804-64-qr: 1

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

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform breakdown:

• windows10-64-devedition: 1

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

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux1804-64-shippable: 1

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

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-release: 1

Platform breakdown:

• linux1804-64-shippable-qr: 1

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

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 1
• mozilla-central: 1
• autoland: 1

Platform breakdown:

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

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

Comment 7

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

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

Comment 8

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

New occurrence: https://treeherder.mozilla.org/logviewer.html#?job_id=303620379&repo=try

Comment 9

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform breakdown:

• windows10-64-shippable: 1

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

Comment 10

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform breakdown:

• windows10-64-shippable: 1

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

Comment 11

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1
• try: 1

Platform breakdown:

• windows10-64-shippable: 2

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

Comment 12

[Razvan Maries]

There are 22 total failures in the last 7 days: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2020-06-14&endday=2020-06-21&tree=trunk&bug=1620767

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=306997709&repo=autoland&lineNumber=6540

Jan, could you assign this to someone?

Comment 13

[Intermittent Failures Robot]

22 failures in 4035 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 18
• mozilla-central: 4

Platform breakdown:

• windows10-64: 1
• windows10-64-shippable: 11
• windows7-32-shippable: 10

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

Comment 14

[Jan Honza Odvarko [:Honza] (always need-info? me) PTO July 8 - 26]

David, this test is related to the Storage panel.
Do you think you could look at that?

Thanks,
Honza

Comment 15

[David Walsh :davidwalsh]

I should be able to look at this Honza!

Comment 16

[Intermittent Failures Robot]

34 failures in 5252 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: 27
• mozilla-central: 7

Platform breakdown:

• windows10-64-shippable: 19
• windows7-32-shippable: 7
• windows10-64: 8

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

Comment 17

[David Walsh :davidwalsh]

:bdanforth Any thoughts on what could be causing this intermittent? I'm wondering if it was a result of:

https://hg.mozilla.org/mozilla-central/rev/dedca1647cfe5f15b57580b8224b32022f9373e3

Comment 18

[Bianca Danforth [:bdanforth]]

(In reply to David Walsh :davidwalsh from comment #17)

:bdanforth Any thoughts on what could be causing this intermittent? I'm wondering if it was a result of:

https://hg.mozilla.org/mozilla-central/rev/dedca1647cfe5f15b57580b8224b32022f9373e3

Hmm… It's possible, though thinking about it, I think this may be Bug 1597900, i.e. a test-only race condition from Bug 1542035.

I just noticed in Bug 1618059, this failing task (test_panel_live_reload) was pulled out from the test and made into a separate test, test_extension_storage_actor_upgrade.js by jdescottes and disabled on Windows. That just landed in central a day ago. Perhaps this bug should be updated to reflect that?

Either way, that doesn't address the root cause…

This test upgrades a test extension while the Storage panel is open. My best guess is that the storage actor is still targeting the fallback window (Or perhaps no window? See error below.) when getStoreObjects is called in these rare instances. Specifically, we have some logic to return no data if the storage actor is targeting a fallback window.

I haven't been able to get the test to fail locally, but looking at the more recent logs in Comment 8 this theory may be further supported by an error that logs just before the assertion fails:

DBG-TEST: resource://devtools/server/actors/targets/browsing-context.js:390: error: NS_ERROR_NOT_AVAILABLE: Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIDocShell.domWindow]

While we wait for the extension to upgrade, we don't explicitly wait for the storage actor to be targeting the extension page before calling getStoreObjects in the test. Perhaps there is a way to do that?

Of course, I could be totally off base; it has been a while. Rpl was my mentor on this work; rpl, what do you think about this theory? Is there a change we could make in the test or elsewhere that would avoid this issue?

jdescottes mentions in the separate test comments that the test started failing a lot "...as soon as we start auto-attaching targets". jdescottes: I would also be curious if you have any thoughts here?

Comment 19

[Julian Descottes [:jdescottes]]

I just noticed in Bug 1618059, this failing task (test_panel_live_reload) was pulled out from the test and made into a separate test, test_extension_storage_actor_upgrade.js by jdescottes and disabled on Windows. That just landed in central a day ago.

Sheriffs disabled the test on windows first, then I landed my patch to split the tests and re-enable on windows. So now it should be enabled everywhere again :)

But after that Bug 1650221 got filed and seems to show that the failure came back. See my comments on this other bug, but basically when I split the test 8 days ago, the test was running fine in --verify. But when I landed it one week after, it was failing often again with --verify.

Considering the failure probably comes down to a race condition (eg an event/change we don't wait on as you suggest), something must have landed in between which makes the test intermittent again, but I don't think it's worth bisecting.

Perhaps this bug should be updated to reflect that?

I agree and we should probably keep the discussion in a single place.

While we wait for the extension to upgrade, we don't explicitly wait for the storage actor to be targeting the extension page before calling getStoreObjects in the test. Perhaps there is a way to do that?

I completely agree with your analysis.
I tried doing something like that in https://phabricator.services.mozilla.com/D82166 (for Bug 1650221). I don't know about a proper event to do that, so I simply waitUntil the storage actor gets populated.

Regarding the auto-attach comment, I am not yet sure why this makes the test fail. When the target is not "attached" it means a few things, but most importantly here, it means we don't react to docshells being created or destroyed. So I guess that what happened before we attached was that the storage actor was actually not updated after the upgrade.

It would be interesting to do a little test: stop auto-attaching in the webextension descriptor front, try to modify the content of the storage for the upgraded extension, and see if it updates at all. If it doesn't update, it means that when testing with a "detached" target, we actually never reacted to the upgrade, and the storage actor was just returning stale data from the earlier version of the addon?

Comment 20

[Julian Descottes [:jdescottes]]

It would be interesting to do a little test: stop auto-attaching in the webextension descriptor front, try to modify the content of the storage for the upgraded extension, and see if it updates at all. If it doesn't update, it means that when testing with a "detached" target, we actually never reacted to the upgrade, and the storage actor was just returning stale data from the earlier version of the addon?

I just tested that and whether we attach or not, we are still able to see updated data after the extension upgrade.

I tried to add as many logs as possible, and as far as I can tell this is really a race between populateStoresForHost (which is fairly async, see https://searchfox.org/mozilla-central/rev/e11d919cdc8a909354eb2c3e19904d9229c55d88/devtools/server/actors/storage.js#1869) and the call to getStoreObjects performed in the test.

populateStoresForHost is called when we upgrade the extension, but it doesn't always have time to actually add the values before the test calls getStoreObjects. However I still can't find why attaching the target makes this race condition much more frequent. I guess it adds more work around the extension upgrade both in the parent and extension processes (since we need to react to the new docshell). So it could make sense that populateStoresForHost needs to wait more before it can complete its work when the target is attached.

I think for now the patch at https://phabricator.services.mozilla.com/D82166 should definitely fix this.

Comment 21

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 6
• mozilla-esr78: 2

Platform breakdown:

• windows7-32-shippable: 2
• windows10-64-shippable: 5
• windows10-64-devedition: 1

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

Comment 22

[Bianca Danforth [:bdanforth]]

Thanks a lot jdescottes for your thoughts and efforts. I similarly don't know if there is a more proper way to do it, but I agree that your patch from Bug 1650221 ought to fix it.

We should be able to safely disregard the most recent failure report above, since your fix landed a day after. Hopefully this bug will close itself after no more failures are observed.

Comment 23

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 8

Platform breakdown:

• windows10-64-devedition: 3
• windows10-64-shippable: 3
• windows7-32-devedition: 2

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

Comment 24

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 4
• try: 1

Platform breakdown:

• windows10-64-devedition: 1
• windows7-32-shippable: 2
• windows10-64-shippable: 1
• windows7-32-devedition: 1

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

Comment 25

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

I'm sorry Bianca (and Julian) for not being able to look into this any sooner.

Today I did look a bit into it, I can still reproduce the issue locally (on the test as splitted by Bug 1650221 into a separate test file and with the asyncWaitUntil workaround removed) and based on what I've been able to see the intermittent failure seems to be due to the fact that:

• populating the store is an asynchronous operation for the extensionStorage actor (see the populateStoresForHost method as defined for the extensionStorage actor here)

• but the extensionStorage actor's getStoredObjects RDP method is currently synchronous and it would return the stored data cached in the actor at the time when it has been called

• when we call getStoredObjects right after the extension has been upgraded, the stored data previously cached by the actor would have been cleared and then it will be repopulated by the onWindowCreated event listener, and then an RDP event would be emitted to make sure that the storage panel is refreshed with that data (see this onWindowCreated fragment here)

I'm not sure what did make the intermittent more frequent, but the intermittency seems kind of expected given what I described above (and the related code linked).

To double-check what I described above I tried to replace the workaround based on the asyncWaitUntil helper with just waiting for storageFront.once("stores-update") and the test did seem to pass the test-verify consistently when I did run it locally.

I'm going to attach that patch to this bug and I'll push it to try to double-check that it is also stable when running on windows builds.

Comment 26

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

Attachment: Bug 1620767 - Fix test_extension_storage_actor_upgrade intermittency by explicitly waiting the stores-update RDP event. r?jdescottes!

Comment 27

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/cb5bc98d8aab
Fix test_extension_storage_actor_upgrade intermittency by explicitly waiting the stores-update RDP event. r=jdescottes

Comment 28

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/cb5bc98d8aab

Comment 29

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 1
• mozilla-release: 1

Platform breakdown:

• windows7-32-devedition: 1
• windows7-32-shippable: 1

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

Comment 30

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-esr78: 1

Platform breakdown:

• windows10-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1620767&startday=2020-12-14&endday=2020-12-20&tree=all

Comment 32

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-esr78: 1

Platform and build breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1620767&startday=2021-05-24&endday=2021-05-30&tree=all

Comment 33

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-esr78: 1

Platform and build breakdown:

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

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