Closed Bug 1399348 Opened 7 years ago Closed 6 years ago

Intermittent browser/components/extensions/test/browser/test-oop-extensions/browser_ext_tabs_executeScript_bad.js | Uncaught exception - [Exception... "Component returned failure code: 0x80520015 (NS_ERROR_FILE_ACCESS_DENIED) [nsIFile.createUnique]"

Categories

(WebExtensions :: Untriaged, defect, P2)

Product:
WebExtensions
Component:
Untriaged
Type:
defect

Tracking

(firefox-esr60 fixed, firefox61 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla61
Tracking Flags:
Tracking Status
firefox-esr60 --- fixed
firefox61 --- fixed

People

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

References

Details

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

Attachments

(1 file)

Bug 1399348 - Explicitly wait and check for error in test browser_ext_tabs_executeScript_bad
59 bytes, text/x-review-board-request
rpl
: review+
Details
Whiteboard: [stockwell needswork]
In the last 7 days, there have been 33 failures.

The failures occur on Windows 7, Windows 7-32 (disabled and nightly) and Windows 10-64 (enabled and disabled).
The build types affected are pgo, opt and debug. 

Log example: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=142195610&lineNumber=4412

And a relevant part of the log were the test failed:

23:29:28     INFO -  1860 INFO TEST-START | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget_window_open.js
5933
23:29:29     INFO -  Not taking screenshot here: see the one that was previously logged
5934
23:29:29     INFO -  Buffered messages logged at 23:29:28
5935
23:29:29     INFO -  1861 INFO Entering test bound test_window_open
5936
23:29:29     INFO -  Buffered messages finished
5937
23:29:29    ERROR -  1862 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget_window_open.js | Uncaught exception - [Exception... "Component returned failure code: 0x80520015 (NS_ERROR_FILE_ACCESS_DENIED) [nsIFile.createUnique]"  nsresult: "0x80520015 (NS_ERROR_FILE_ACCESS_DENIED)"  location: "JS frame :: resource://testing-common/ExtensionTestCommon.jsm :: generateZipFile :: line 271"  data: no]
5938
23:29:29     INFO -  Stack trace:
5939
23:29:29     INFO -      generateZipFile@resource://testing-common/ExtensionTestCommon.jsm:271:5
5940
23:29:29     INFO -      generateXPI@resource://testing-common/ExtensionTestCommon.jsm:263:12
5941
23:29:29     INFO -      generate@resource://testing-common/ExtensionTestCommon.jsm:357:16
5942
23:29:29     INFO -      generate@resource://gre/modules/Extension.jsm:1148:12
5943
23:29:29     INFO -      _receiveMessageAPI@chrome://mochikit/content/tests/SimpleTest/SpecialPowersObserverAPI.js:579:25
5944
23:29:29     INFO -      ChromePowers.prototype._receiveMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:83:14
5945
23:29:29     INFO -      ChromePowers.prototype._sendAsyncMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:45:3
5946
23:29:29     INFO -      loadExtension@chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:2037:5
5947
23:29:29     INFO -      ExtensionTestUtils.loadExtension@chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:105:19
5948
23:29:29     INFO -      test_window_open@chrome://mochitests/content/browser/browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget_window_open.js:47:21
5949
23:29:29     INFO -      Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:806:21
5950
23:29:29     INFO -      Tester_execTest@chrome://mochikit/content/browser-test.js:797:9
5951
23:29:29     INFO -      Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:697:9
5952
23:29:29     INFO -      SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
5953
23:29:29     INFO -  1863 INFO Leaving test bound test_window_open
5954
23:29:29     INFO -  1864 INFO Entering test bound test_window_open_close_from_browserAction_popup
5955
23:29:29     INFO -  Not taking screenshot here: see the one that was previously logged
5956
23:29:29    ERROR -  1865 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget_window_open.js | Uncaught exception - [Exception... "Component returned failure code: 0x80520015 (NS_ERROR_FILE_ACCESS_DENIED) [nsIFile.createUnique]"  nsresult: "0x80520015 (NS_ERROR_FILE_ACCESS_DENIED)"  location: "JS frame :: resource://testing-common/ExtensionTestCommon.jsm :: generateZipFile :: line 271"  data: no]
5957
23:29:29     INFO -  Stack trace:
5958
23:29:29     INFO -      generateZipFile@resource://testing-common/ExtensionTestCommon.jsm:271:5
5959
23:29:29     INFO -      generateXPI@resource://testing-common/ExtensionTestCommon.jsm:263:12
5960
23:29:29     INFO -      generate@resource://testing-common/ExtensionTestCommon.jsm:357:16
5961
23:29:29     INFO -      generate@resource://gre/modules/Extension.jsm:1148:12
5962
23:29:29     INFO -      _receiveMessageAPI@chrome://mochikit/content/tests/SimpleTest/SpecialPowersObserverAPI.js:579:25
5963
23:29:29     INFO -      ChromePowers.prototype._receiveMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:83:14
5964
23:29:29     INFO -      ChromePowers.prototype._sendAsyncMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:45:3
5965
23:29:29     INFO -      loadExtension@chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:2037:5
5966
23:29:29     INFO -      ExtensionTestUtils.loadExtension@chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:105:19
5967
23:29:29     INFO -      test_window_open_close_from_browserAction_popup@chrome://mochitests/content/browser/browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget_window_open.js:110:21
5968
23:29:29     INFO -      Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:806:21
5969
23:29:29     INFO -      Tester_execTest@chrome://mochikit/content/browser-test.js:797:9
5970
23:29:29     INFO -      Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:697:9
5971
23:29:29     INFO -      SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
5972
23:29:29     INFO -  1866 INFO Leaving test bound test_window_open_close_from_browserAction_popup
5973
23:29:29     INFO -  GECKO(4952) | MEMORY STAT | vsize 989MB | vsizeMaxContiguous 515MB | residentFast 376MB | heapAllocated 118MB
5974
23:29:29     INFO -  1867 INFO TEST-OK | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget_window_open.js | took 646ms
5975
23:29:29     INFO -  Not taking screenshot here: see the one that was previously logged
5976
23:29:29    ERROR -  1868 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget_window_open.js | Found an unexpected tab at the end of test run: http://mochi.test:8888/browser/browser/components/extensions/test/browser/webNav_createdTargetSource.html -
5977
23:29:29     INFO -  Not taking screenshot here: see the one that was previously logged
5978
23:29:29    ERROR -  1869 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget_window_open.js | Found an unexpected tab at the end of test run: http://mochi.test:8888/browser/browser/components/extensions/test/browser/webNav_createdTargetSource.html -
5979
23:29:29     INFO -  1870 INFO checking window state

:andym, I see that you are the triage owner, can you help find someone to look into this test?
Flags: needinfo?(amckay)
I will try to take a look at this one as well.
Assignee: nobody → bob.silverberg
Flags: needinfo?(amckay)
Priority: -- → P2
In the last week there have been 49 failures.
The failures occur on windows 7 and windows10-64 plaforms.
Affected build types: opt and pgo.

Since November 12th, the number of failures seems to be decreasing.

Here is a recent log file with the failure: 
https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=144408050

and relevant snippet from it:

21:20:46     INFO -  788 INFO Entering test bound testMatchDataURI
3755
21:20:46     INFO -  Buffered messages finished
3756
21:20:46    ERROR -  789 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_tabs_executeScript_bad.js | Uncaught exception - [Exception... "Component returned failure code: 0x80520015 (NS_ERROR_FILE_ACCESS_DENIED) [nsIFile.createUnique]"  nsresult: "0x80520015 (NS_ERROR_FILE_ACCESS_DENIED)"  location: "JS frame :: resource://testing-common/ExtensionTestCommon.jsm :: generateZipFile :: line 269"  data: no]
3757
21:20:46     INFO -  Stack trace:
3758
21:20:46     INFO -      generateZipFile@resource://testing-common/ExtensionTestCommon.jsm:269:5
3759
21:20:46     INFO -      generateXPI@resource://testing-common/ExtensionTestCommon.jsm:261:12
3760
21:20:46     INFO -      generate@resource://testing-common/ExtensionTestCommon.jsm:355:16
3761
21:20:46     INFO -      generate@resource://gre/modules/Extension.jsm:1141:12
3762
21:20:46     INFO -      _receiveMessageAPI@chrome://mochikit/content/tests/SimpleTest/SpecialPowersObserverAPI.js:579:25
3763
21:20:46     INFO -      ChromePowers.prototype._receiveMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:83:14
3764
21:20:46     INFO -      ChromePowers.prototype._sendAsyncMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:45:3
3765
21:20:46     INFO -      loadExtension@chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:2037:5
3766
21:20:46     INFO -      ExtensionTestUtils.loadExtension@chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:105:19
3767
21:20:46     INFO -      testMatchDataURI@chrome://mochitests/content/browser/browser/components/extensions/test/browser/browser_ext_tabs_executeScript_bad.js:212:18
3768
21:20:46     INFO -      Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1065:21
3769
21:20:46     INFO -      Tester_execTest@chrome://mochikit/content/browser-test.js:1056:9
3770
21:20:46     INFO -      Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:956:9
3771
21:20:46     INFO -      SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
3772
21:20:46     INFO -  790 INFO Leaving test bound testMatchDataURI
Flags: needinfo?(bob.silverberg)
I took a look at this but I'm not sure exactly what's causing the problem nor what a fix would be.

The error is coming from the call to file.createUnique [1] in generateZipFile in ExtensionTestCommon.jsm, with the error message "NS_ERROR_FILE_ACCESS_DENIED".

I was able to reproduce the failure on my Windows VM via —verify, with the failure occurring at different points in the suite of tests on different runs. I’m wondering if the content script that is being attempted in the default tab, which is meant to fail, isn’t running/completing before the test ends and therefore is somehow preventing the zip file from being removed.

To test that theory I added a sleep of 1000ms immediately before the call to `await extension.unload();` in testHasNoPermission, and after doing so I was unable to reproduce the failure on Windows. 

Kris, if this is in fact what is causing the failure, what can we do about it?

[1] https://searchfox.org/mozilla-central/source/toolkit/components/extensions/ExtensionTestCommon.jsm#269
Flags: needinfo?(bob.silverberg) → needinfo?(kmaglione+bmo)
39 Total failures in the last week.
 
Occurrences per platform:
 - 21 windows10-64
 - 17 Windows 7
 -  1 windows7-32-stylo-disabled
 
Occurrences per build type:
 - 19 pgo 
 - 15 opt
 -  5 debug
 
  
Here is a relevant recent log: 
https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=146952409

and a relevant snippet from it:

23:15:09     INFO -  1278 INFO Console message: Ignoring response to aborted listener for 549755813925
3956
23:15:09     INFO -  1279 INFO Console message: Cannot send function call result: other side closed connection (call data: ({path:"tabs.executeScript", args:[null, {allFrames:null, code:null, cssOrigin:null, file:"script.js", frameId:null, matchAboutBlank:null, runAt:"document_idle"}]}))
3957
23:15:09     INFO -  1280 INFO Test active tab, commands, no key press
3958
23:15:09     INFO -  Buffered messages finished
3959
23:15:09    ERROR -  1281 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_tabs_executeScript_bad.js | Uncaught exception - [Exception... "Component returned failure code: 0x80520015 (NS_ERROR_FILE_ACCESS_DENIED) [nsIFile.createUnique]"  nsresult: "0x80520015 (NS_ERROR_FILE_ACCESS_DENIED)"  location: "JS frame :: resource://testing-common/ExtensionTestCommon.jsm :: generateZipFile :: line 269"  data: no]
3960
23:15:09     INFO -  Stack trace:
3961
23:15:09     INFO -      generateZipFile@resource://testing-common/ExtensionTestCommon.jsm:269:5
3962
23:15:09     INFO -      generateXPI@resource://testing-common/ExtensionTestCommon.jsm:261:12
3963
23:15:09     INFO -      generate@resource://testing-common/ExtensionTestCommon.jsm:355:16
3964
23:15:09     INFO -      generate@resource://gre/modules/Extension.jsm:1141:12
3965
23:15:09     INFO -      _receiveMessageAPI@chrome://mochikit/content/tests/SimpleTest/SpecialPowersObserverAPI.js:579:25
3966
23:15:09     INFO -      ChromePowers.prototype._receiveMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:83:14
3967
23:15:09     INFO -      ChromePowers.prototype._sendAsyncMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:45:3
3968
23:15:09     INFO -      loadExtension@chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:2037:5
3969
23:15:09     INFO -      ExtensionTestUtils.loadExtension@chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:105:19
3970
23:15:09     INFO -      testHasNoPermission@chrome://mochitests/content/browser/browser/components/extensions/test/browser/browser_ext_tabs_executeScript_bad.js:47:19
3971
23:15:09     INFO -      async*testBadPermissions@chrome://mochitests/content/browser/browser/components/extensions/test/browser/browser_ext_tabs_executeScript_bad.js:168:9
3972
23:15:09     INFO -      Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1065:21
3973
23:15:09     INFO -      Tester_execTest@chrome://mochikit/content/browser-test.js:1056:9
3974
23:15:09     INFO -      Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:956:9
3975
23:15:09     INFO -      SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
3976
23:15:09     INFO -  1282 INFO Leaving test bound testBadPermissions

:kmag, could you please have a look?
34 Total failures in the last week.
 
Occurrences per platform:
 - 19 windows10-64
 - 15 Windows 7

Occurrences per build type:
 - 16 pgo 
 - 12 opt
 -  6 debug

Here is a recent log file and a snippet from it: 
https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=155781410

00:00:14     INFO -  758 INFO Leaving test bound testBadPermissions
3939
00:00:14     INFO -  759 INFO Entering test bound testMatchDataURI
3940
00:00:14     INFO -  Buffered messages finished
3941
00:00:14    ERROR -  760 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_tabs_executeScript_bad.js | Uncaught exception - [Exception... "Component returned failure code: 0x80520015 (NS_ERROR_FILE_ACCESS_DENIED) [nsIFile.createUnique]"  nsresult: "0x80520015 (NS_ERROR_FILE_ACCESS_DENIED)"  location: "JS frame :: resource://testing-common/ExtensionTestCommon.jsm :: generateZipFile :: line 271"  data: no]
3942
00:00:14     INFO -  Stack trace:
3943
00:00:14     INFO -      generateZipFile@resource://testing-common/ExtensionTestCommon.jsm:271:5
3944
00:00:14     INFO -      generateXPI@resource://testing-common/ExtensionTestCommon.jsm:263:12
3945
00:00:14     INFO -      generate@resource://testing-common/ExtensionTestCommon.jsm:357:16
3946
00:00:14     INFO -      _receiveMessageAPI@chrome://mochikit/content/tests/SimpleTest/SpecialPowersObserverAPI.js:583:25
3947
00:00:14     INFO -      ChromePowers.prototype._receiveMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:83:14
3948
00:00:14     INFO -      ChromePowers.prototype._sendAsyncMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:45:3
3949
00:00:14     INFO -      loadExtension@chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:2039:5
3950
00:00:14     INFO -      ExtensionTestUtils.loadExtension@chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:105:19
3951
00:00:14     INFO -      testMatchDataURI@chrome://mochitests/content/browser/browser/components/extensions/test/browser/test-oop-extensions/browser_ext_tabs_executeScript_bad.js:212:18
3952
00:00:14     INFO -      Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1065:21
3953
00:00:14     INFO -      Tester_execTest@chrome://mochikit/content/browser-test.js:1056:9
3954
00:00:14     INFO -      Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:956:9
3955
00:00:14     INFO -      SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
3956
00:00:14     INFO -  761 INFO Leaving test bound testMatchDataURI


:kmag, any updates on this?
Whiteboard: [stockwell unknown] → [stockwell needswork]
Whiteboard: [stockwell needswork] → [stockwell needswork:owner]
Depends on: 1435100
Assignee: bob.silverberg → nobody
Comment on attachment 8970163 [details]
Bug 1399348 - Explicitly wait and check for error in test browser_ext_tabs_executeScript_bad

https://reviewboard.mozilla.org/r/238972/#review245182

::: browser/components/extensions/test/browser/browser_ext_tabs_executeScript_bad.js:20
(Diff revision 1)
> -        // Execute a script we know we have permissions for in the
> +      // Execute a script we know we have permissions for in the
> -        // second tab, in the hopes that it will execute after the
> +      // second tab, in the hopes that it will execute after the
> -        // first one. This has intermittent failure written all over
> +      // first one.
> -        // it, but it's just about the best we can do until we
> -        // support callbacks for executeScript.
> -        browser.tabs.executeScript(tabs[1].id, {
> +      browser.tabs.executeScript(tabs[1].id, {
> -          file: "second-script.js",
> +        file: "second-script.js",
> -        });
> +      });

It looks that this second browser.tabs.executeScript was a workaround needed because tabs.executeScript wasn't rejecting (or setting the runtime.lastError property) on failures yet when this test has been created.

can we remove it now?

::: mobile/android/components/extensions/test/mochitest/test_ext_tabs_executeScript_bad.html:36
(Diff revision 1)
> -        browser.tabs.executeScript(tabs[1].id, {
> +      browser.tabs.executeScript(tabs[1].id, {
> -          file: "second-script.js",
> +        file: "second-script.js",
> -        });
> +      });

Same question as the one on the test for Firefox Desktop.
Assigning to me since I attached a patch.

The patch improves the test (makes it more deterministic), but I don't know whether the intermittent will be fixed by it.
Assignee: nobody → rob
Status: NEW → ASSIGNED
Flags: needinfo?(kmaglione+bmo)
Blocks: 1457115
Comment on attachment 8970163 [details]
Bug 1399348 - Explicitly wait and check for error in test browser_ext_tabs_executeScript_bad

https://reviewboard.mozilla.org/r/238972/#review245380

Thanks Rob, getting rid of the "PromiseTestUtils.whitelistRejectionsGlobally" (introduced by Bug 1242505) in favor of "catching the rejection of the (expected) invalid tabs.executeScript" sounds good to me.

As briefly discussed over IRC, as long as we have a filed issue related to remove the second tabs.executeScript call (that was previously used as a workaround for the missing callback/returned promise support in tabs.executeScript), I'm ok with this change in the meantime, and see if it was enough to fix the remaining intermittency of this test.

r+ on green try 
(well, "green as much as it was before" ;-), given that this test was still already failing intermittently, even if less often after we landed the fix from Bug 1435100).

::: browser/components/extensions/test/browser/browser_ext_tabs_executeScript_bad.js:342
(Diff revision 2)
>  // TODO: Test that |executeScript| fails if the tab has navigated to a
>  // new page, and no longer matches our expected state. This involves
> -// intentionally trying to trigger a race condition, and is probably not
> +// intentionally trying to trigger a race condition.

This TODO sounds a lot like a test for a scenario pretty similar to the one described by Bug 1452045.

I think that it could be worth to mention that bug number on this TODO (and maybe comment in that bugzilla issue that once we fix and write a test for Bug 1452045, we can remove this TODO).
Attachment #8970163 - Flags: review?(lgreco) → review+
Adding leave-open so that we know whether the intermittents are really solved.

The separately filed bug 1457115 will remind me of this bug, so if the intermittents are solved I will close this bug by then.
Keywords: leave-open
Pushed by rob@robwu.nl:
https://hg.mozilla.org/integration/autoland/rev/dd9ba54d497c
Explicitly wait and check for error in test browser_ext_tabs_executeScript_bad r=rpl
See Also: → 1463489
The intermittents disappeared completely, which confirms my suspicion that something was wrong with resource locking and dynamic scripts.

I filed bug 1463489 with the findings of the investigation.

Now I have obtained the results, the test can be simplified further (bug 1457115).
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Keywords: leave-open
Resolution: --- → FIXED
status-firefox61: --- → fixed
status-firefox-esr60: --- → affected
Target Milestone: --- → mozilla61
Flags: qe-verify-
See Also: → 1466477
Product: Toolkit → WebExtensions
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: