1902011 - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript.html | Unexpected execution

Status: RESOLVED FIXED

(WebExtensions :: General, defect, P2)

Description

[Rob Wu [:robwu]]

I was looking through failures in bug 1781607, and spotted multiple examples of cases where scripting.executeScript managed to execute despite the extension not having any permissions. We should understand why this is happening and fix the underlying issue if any.

• test_executeScript_with_wrong_host_permissions (source link)
• test_executeScript_with_frameId_and_wrong_host_permission (source link)

Below are two representative examples of many.

Linux opt ccov
https://treeherder.mozilla.org/logviewer?job_id=460274008&repo=mozilla-central&lineNumber=8812

[task 2024-05-30T05:12:45.302Z] 05:12:45 INFO - add_task | Entering test_executeScript_with_wrong_host_permissions
[task 2024-05-30T05:12:45.303Z] 05:12:45 INFO - Extension loaded
[task 2024-05-30T05:12:45.303Z] 05:12:45 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript.html | expected 1 tab - Expected: 1, Actual: 1
[task 2024-05-30T05:12:45.306Z] 05:12:45 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript.html | Unexpected execution
...
[task 2024-05-30T05:12:45.313Z] 05:12:45 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript.html | Promise resolved, expected rejection '"Missing host permission for the tab"': expected host permission error

Linux opt condprof
https://treeherder.mozilla.org/logviewer?job_id=460715714&repo=autoland&lineNumber=15399

[task 2024-06-02T09:01:54.304Z] 09:01:54 INFO - add_task | Entering test_executeScript_with_frameId_and_wrong_host_permission
[task 2024-06-02T09:01:54.305Z] 09:01:54 INFO - Extension loaded
[task 2024-06-02T09:01:54.305Z] 09:01:54 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript.html | expected 1 tab - Expected: 1, Actual: 1
[task 2024-06-02T09:01:54.306Z] 09:01:54 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript.html | expected 3 frames - Expected: 3, Actual: 3
[task 2024-06-02T09:01:54.307Z] 09:01:54 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript.html | Unexpected execution
...
[task 2024-06-02T09:01:54.309Z] 09:01:54 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript.html | Promise resolved, expected rejection '"Missing host permission for the tab or frames"': got the expected error message

Comment 1

[Rob Wu [:robwu]]

Of the 95 failures in the past 4 months (https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1781607&startday=2024-02-14&endday=2024-06-09&tree=all):

• 65 are associated with this bug
• 8 are associated with another lower-frequency unexpected code execution (see below).
• 7 are timeouts (e.g. on ASAN).

The third "executed unexpectedly" error is in the last test of the file:

• test_executeScript_with_allFrames_and_wrong_host_permissions (source link)

The logs below shows that the code executed 3 times instead of 2 times, even though the tab only has a top-level mochitest runner containing the mochitest in a frame (for which the test extension has host permissions), and a cross-origin frame for which the test extension does not have permissions. The screenshot of this test shows this described frame tree (rooted at http://mochi.test:8888/) and doesn't contain any other unexpected content.

Windows opt (xorig, but also seen on ccov, regular tests)
https://treeherder.mozilla.org/logviewer?job_id=459868921&repo=autoland&lineNumber=13896
Screenshot: https://firefoxci.taskcluster-artifacts.net/Xw7ghky4RnOMntUOmIInvA/0/public/test_info/mozilla-test-fail-screenshot_uijs8myc.png

[task 2024-05-28T00:28:55.359Z] 00:28:55 INFO - add_task | Entering test_executeScript_with_allFrames_and_wrong_host_permissions
[task 2024-05-28T00:28:55.360Z] 00:28:55 INFO - Extension loaded
[task 2024-05-28T00:28:55.361Z] 00:28:55 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript.html | expected 1 tab - Expected: 1, Actual: 1
[task 2024-05-28T00:28:55.362Z] 00:28:55 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript.html | expected 3 frames - Expected: 3, Actual: 3
[task 2024-05-28T00:28:55.362Z] 00:28:55 INFO - Buffered messages finished
[task 2024-05-28T00:28:55.366Z] 00:28:55 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript.html | got expected number of results - Expected: 2, Actual: 3
[task 2024-05-28T00:28:55.366Z] 00:28:55 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:426:16
[task 2024-05-28T00:28:55.366Z] 00:28:55 INFO - testHandler@SimpleTest/ExtensionTestUtils.js:83:18
[task 2024-05-28T00:28:55.366Z] 00:28:55 INFO - testResult@SimpleTest/ExtensionTestUtils.js:97:18
[task 2024-05-28T00:28:55.366Z] 00:28:55 INFO - Async*test_executeScript_with_allFrames_and_wrong_host_permissions@toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript.html?currentTestURL=toolkit%2Fcomponents%2Fextensions%2Ftest%2Fmochitest%2Ftest_ext_scripting_executeScript.html&closeWhenDone=1&showTestReport=false&expected=pass:1470:21

Comment 2

[Rob Wu [:robwu]]

I audited the code base, and all logic seems correct, except for a case. For the scenario, scroll to the end, to the "Scenario that triggers failure".

• Code execution access [is checked by matchesWindowGlobal]((https://searchfox.org/mozilla-central/rev/4c8627a76e2e0a9b49c2b673424da478e08715ad/toolkit/components/extensions/ExtensionContent.sys.mjs#1315), which is eventually handled by MozDocumentMatcher::MatchesWindowGlobal and in its turn MozDocumentMatcher::Matches
• MozDocumentMatcher::Matches only returns true in a few cases, which I explicitly enumerate below.
  • lines 820-838 If the document is a top-level about:document without origin, and the extension has active tab or <all_urls> permission. These conditions are unlikely to have been met:
    • There is no top-level about:blank.
    • The test extensions do not have any relevant host permissions (the script's match patterns are derived from extension.allowedOrigins). With the extension not declaring any host permission, the only value that allowedOrigins is supposed to contain is the moz-extension://UUID origin of the extension).
    • mHasActiveTabPermission is unlikely to be true. While MV3 extensions do not require activeTab to set the hasActiveTabPermission flag, there is nothing in the test that marks the tab as active tab (and even if the logic were to be called, the test extension does not have the tab URL listed in its optional origin permissions).
  • lines 864 - 868 If the extension has active tab access, and the target document is same-origin to the top, and the URL is one of the patterns permitted by <all_urls>. Again, not likely to have been met:
    • mHasActiveTabPermission is unlikely to be true as mentioned before.
    • In case of test_executeScript_with_frameId_and_wrong_host_permission, the deepest frame is certainly cross-origin to the top frame, and definitely not same-origin.
    • <all_urls> matches if the frame's origin is from the scheme http(s), ws(s), file: or data:. The expected documents are all from http(s). Note that moz-extension: is explicitly not part of <all_urls>, so that is not allowed through this logic.
  • line 871 - 873 If not MV3, and has active tab access and either same-origin to top or the initial frame of the document. Unlikely again:
    • mHasActiveTabPermission is unlikely to be true as mentioned before.
    • "not MV3" is false: the test extension is MV3. "not extension" would also be "not MV3", but since this MozDocumentMatcher instance is a subclass of WebExtensionContentScript, extension is guaranteed to be set.
      • ... unless mExtension is cleared (e.g. through the GC implementation). But it is a RefPtr owned by the WebExtensionContentScript, which in turn is strongly referenced through the script that is still within the closure when the decision to inject is made (references: policy -> WebExtensionContentScript (aka matcher) -> script).
        mHasActiveTabPermission
• lines 884-913 If MatchesURI is true. Unlikely, because:
  • As mentioned before, matches is set to extension.allowedOrigins in parent/ext-scripting.js. As mentioned before, the test extension doesn't have any host permissions, so allowedOrigins only contains the moz-extension:-pattern and that does not match the document's http(s) origin.
  • MV3 extensions are also forced to verify the host permissions (source), which again confirms that the extension is allowed access to the given document. Which is also derived from extension.allowedOrigins in the parent.

Based on the above analysis, it seems impossible to have reached the condition that the test is asserting against. So we now have to imagine the unlikely to have been possible, and I have considered various scenarios:

• Somehow a moz-extension:-document is matched: because moz-extension: is part of the allowedOrigins, if a moz-extension:-document appeared in the frame tree (or the tab), execution could happen if it were to be chosen as the active tab.
  • There is nothing that attempts to load the test extension in any document. And even if it were, web_accessible_resources would have prevented embedding.
  • I also confirmed that it is not possible for the extension browser to have been returned when "active tab" was looked up. The extension's background page is the only such document, and part of the HiddenXULWindow that is definitely not a navigator:browser (thus not considered a browser window). Even if it happened by some freak accident, then the window does not have the required gBrowser global, so it could never be mistaken for the active tab that browser.tabs.query({ active: true }) looks up.
• Somehow the http(s) origin (or even broader) host permission was added to allowedOrigins. There are several places that update allowedOrigins:
  • I checked _setupStartupPermissions and other places that update allowedOrigins, but these are logically sound.
  • loadManifest is the first, initializes from the parsed manifest.
    • parseManifest adds optional permissions if they have been saved to the disk before. This is keyed by the extension's ID.
    • There is no check to confirm whether the saved permission is within the set of optional permissions granted to the extension (which I filed before as bug 1766915).
    • Since the test extension does not have an ID in its browser_specific_settings and is unsigned (just a zip file), an ID is generated at install time based on the file
    • ... in fact it is a hash based on the file path and a random salt that is constant for the duration of the session.
    • the generated file name is "generated-extension.xpi", and if it already exists, "generated-extension-1.xpi", etc.. This is rather predictable and shared across many unit tests.

Scenario that triggers failure

The last point above seems the most likely path towards triggering this issue. I can imagine this happening as follows:

• A previous extension left some permission state behind in the database or memory of the ExtensionPermissions.sys.mjs backend, for a temporarily generated add-on without extension ID.
  • In test_ext_scripting_executeScript.html test itself, the first test task generates a dummy extension with multiple relevant host permissions. After that, the next test is test_executeScript_with_wrong_host_permission.
    • There is a ExtensionPermissions.add call without awaiting the promise. It is theoretically possible for this to take a while, potentially past shutdown of the first test extension.
• When test_executeScript_with_wrong_host_permission is run, the generated extension file name coincides with a previously generated file name, resulting in the same extension ID, and consequently the previously stored permissions are reused (thanks to bug 1766915).
• This is a race condition, because ordinarily permissions are removed post uninstall via Extension.clearOnUninstall.
  • Side note: in bug 1826390 I landed logic that awaits completion of removal before considering "shutdown complete", but that did not noticeably impact the reported frequency of the failures associated with this test.

I simulated the scenario above and can reproduce the exact error.

Comment 3

[Rob Wu [:robwu]]

(linking bug 1766915, because this bug clearly shows why the issue in the other bug can have seemingly alarming consequences).

Comment 4

[Rob Wu [:robwu]]

Attachment: Bug 1902011 - Simulate race condition, see comment 2 - DO NOT LAND

https://bugzilla.mozilla.org/show_bug.cgi?id=1902011#c2

Comment 5

[Rob Wu [:robwu]]

With the test case above that artificially delays ExtensionPermissions._update, the stack trace points to _setupStartupPermissions as the caller. After that, the log shows the same error as the bug report:

 0:13.36 INFO add_task | Entering test_executeScript_params_validation
 0:13.36 INFO Extension loaded
 0:13.40 GECKO(45282) Intercepted ExtensionPermissions call: store[hookedMethodName]@http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript.html:143:54
 0:13.40 GECKO(45282) _update@resource://gre/modules/ExtensionPermissions.sys.mjs:324:17
 0:13.40 GECKO(45282) add@resource://gre/modules/ExtensionPermissions.sys.mjs:439:18
 0:13.40 GECKO(45282) async*_setupStartupPermissions@resource://gre/modules/Extension.sys.mjs:3745:35
 0:13.40 GECKO(45282) startup@resource://gre/modules/Extension.sys.mjs:3597:12
 0:13.40 GECKO(45282) async*startup@resource://gre/modules/Extension.sys.mjs:2806:27
 0:13.40 GECKO(45282) callBootstrapMethod@resource://gre/modules/addons/XPIProvider.sys.mjs:1850:33
 0:13.40 GECKO(45282) startup@resource://gre/modules/addons/XPIProvider.sys.mjs:1971:34
 0:13.40 GECKO(45282) _install@resource://gre/modules/addons/XPIProvider.sys.mjs:2050:18
 0:13.40 GECKO(45282) install@resource://gre/modules/addons/XPIProvider.sys.mjs:2039:17
 0:13.40 GECKO(45282) _activateAddon@resource://gre/modules/addons/XPIInstall.sys.mjs:4748:23
 0:13.40 GECKO(45282) async*installTemporaryAddon@resource://gre/modules/addons/XPIInstall.sys.mjs:4607:16
 0:13.40 GECKO(45282) async*XPIProvider[meth]@resource://gre/modules/addons/XPIProvider.sys.mjs:3330:39
 0:13.40 GECKO(45282) installTemporaryAddon@resource://gre/modules/AddonManager.sys.mjs:2698:7
 0:13.40 GECKO(45282) installTemporaryAddon@resource://gre/modules/AddonManager.sys.mjs:4335:33
 0:13.40 GECKO(45282) startup@resource://testing-common/ExtensionTestCommon.sys.mjs:245:32
...
 0:13.52 INFO add_task | Leaving test_executeScript_params_validation
 0:13.52 INFO add_task | Entering test_executeScript_with_wrong_host_permissions
 0:13.52 INFO Extension loaded
 0:13.55 PASS expected 1 tab - Expected: 1, Actual: 1
 0:13.56 FAIL Unexpected execution
    SimpleTest.ok@SimpleTest/SimpleTest.js:426:16
    testHandler@SimpleTest/ExtensionTestUtils.js:87:18
    testResult@SimpleTest/ExtensionTestUtils.js:97:18
    Async*test_executeScript_with_wrong_host_permissions@toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript.html:192:19
...
 0:13.56 FAIL Promise resolved, expected rejection '"Missing host permission for the tab"': expected host permission error

Comment 6

[Rob Wu [:robwu]]

Attachment: Bug 1902011 - Synchronize concurrent ExtensionPermissions calls

Comment 7

[Rob Wu [:robwu]]

I've fixed the race condition above by running ExtensionPermission operations sequentially.

This does not only fix the race condition, it also improves the performance of the implementation at startup. Previously, it would be possible for ExtensionPermissions.get() to run concurrently. The fast path is to use the data in the StartupCache.permissions where possible, but if it was not, then the async read-from-disk operation was used instead), which would ultimately update StartupCache after the async operation completes. Due to this implementation, any concurrent ExtensionPermissions.get() call would always run asynchronously, and any ExtensionPermissions.get call after the first completion but before the second completion would execute almost instantly (due to the fast path through StartupCache). Now, with the explicitly synchronized access, only the first Extensionpermissions.get (or add, etc.) call would go through the slow path, and any subsequent calls will go through the fast path.

With the patch above, the original test now passes as expected:

 0:13.26 INFO add_task | Entering test_executeScript_params_validation
 0:13.26 INFO Extension loaded
 0:13.29 GECKO(62473) Intercepted ExtensionPermissions call: store[hookedMethodName]@http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript.html:145:54
 0:13.29 GECKO(62473) _update@resource://gre/modules/ExtensionPermissions.sys.mjs:359:17
 0:13.29 GECKO(62473) add/<@resource://gre/modules/ExtensionPermissions.sys.mjs:477:20
 0:13.29 GECKO(62473) async*_synchronizeExtPermAccess/</<@resource://gre/modules/ExtensionPermissions.sys.mjs:338:25
 0:13.29 GECKO(62473) _synchronizeExtPermAccess/<@resource://gre/modules/ExtensionPermissions.sys.mjs:353:17
 0:13.29 GECKO(62473) _synchronizeExtPermAccess@resource://gre/modules/ExtensionPermissions.sys.mjs:331:12
 0:13.29 GECKO(62473) add@resource://gre/modules/ExtensionPermissions.sys.mjs:454:17
 0:13.29 GECKO(62473) _setupStartupPermissions@resource://gre/modules/Extension.sys.mjs:3745:35
...
 0:13.37 PASS The author of the test has indicated that flaky timeouts are expected.  Reason: Simulate slow storage/database access
 0:17.41 GECKO(62473) WARNING: Detected slow post-uninstall task: 4006ms for extension 1957c8469dd4589f6f1b42dbccc86355298ca27f@temporary-addon: Clear ExtensionPermissions for 1957c8469dd4589f6f1b42dbccc86355298ca27f@temporary-addon
 0:18.42 INFO add_task | Leaving test_executeScript_params_validation
 0:18.42 INFO add_task | Entering test_executeScript_with_wrong_host_permissions
 0:18.42 INFO Extension loaded
 0:18.60 PASS expected 1 tab - Expected: 1, Actual: 1
 0:18.65 PASS Promise rejected, expecting rejection to match '"Missing host permission for the tab"', got 'Error: Missing host permission for the tab': expected host permission error
 0:18.65 PASS execute-script
 0:18.65 PASS test result correct
 0:18.69 INFO add_task | Leaving test_executeScript_with_wrong_host_permissions

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/dc0467964374
Synchronize concurrent ExtensionPermissions calls r=willdurand

Comment 9

[Serban Stanca [:SerbanS]]

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