Closed Bug 1792559 Opened 2 years ago Closed 1 year ago

Extension console not logging error raised by callback function handling WebExtensions API events (e.g. webRequest.onBeforeRequest, tabs.onCreated etc.)

Categories

(WebExtensions :: Developer Tools, defect, P3)

Product:
WebExtensions
Component:
Developer Tools
Type:
defect

Tracking

(firefox-esr102 wontfix, firefox105 wontfix, firefox106 wontfix, firefox107 wontfix, firefox108 wontfix, firefox109 wontfix, firefox110 wontfix, firefox111 ?, firefox112 ?, firefox113 ?)

Status:
VERIFIED FIXED
Milestone:
111 Branch
Tracking Flags:
Tracking Status
firefox-esr102 --- wontfix
firefox105 --- wontfix
firefox106 --- wontfix
firefox107 --- wontfix
firefox108 --- wontfix
firefox109 --- wontfix
firefox110 --- wontfix
firefox111 --- ?
firefox112 --- ?
firefox113 --- ?

People

(Reporter: garywill, Assigned: rpl)

References

(Blocks 1 open bug, Regression)

Details

(Keywords: regression, Whiteboard: [addons-jira])

Attachments

(6 files)

bug-demo-ext.zip
895 bytes, application/zip
Details
2022-09-29_12h25_52.png
20.08 KB, image/png
Details
2022-11-01_09h12_25.png
56.35 KB, image/png
Details
Bug 1792559 - BaseContext applySafeWithoutClone should log errors associated to the extension page innerWindowID. r?willdurand!
48 bytes, text/x-phabricator-request
Details | Review
2023-02-09_12h18_58.png
21.32 KB, image/png
Details
2023-03-20_11h06_40.png
18.40 KB, image/png
Details
Attached file bug-demo-ext.zip —

Steps to reproduce:

  1. Run Firefox 105.0.1 with new profile

  2. Go to about:debugging to load a bug-demo extension:

    ---- background.js
console.debug(11);

browser.webRequest.onBeforeRequest.addListener(
    onBeforeRequest_main,
    {urls: ["<all_urls>", "*://*/*", "ws://*/*", "wss://*/*", ], types: ["main_frame"]},
    ["blocking"]
); 

function onBeforeRequest_main(details)
{
    console.log(33);
    var v = not_def_thing; // here error. // firefox console won't show this error
    // not executing below, due to above error
    console.log(v);  
    console.debug(44);  
} 

console.debug(22);

  3. Click "Inspect" and switch to the extension's console

  4. Open a new tab and navigate it to any website

Actual results:

Error from var v = not_def_thing; in webRequest callback function not shown in console

We could see the last shown log is "33".

Expected results:

The error message should show in extension's developer console

The Bugbug bot thinks this bug should belong to the 'WebExtensions::Request Handling' component, and is moving the bug to that component. Please correct in case you think the bot is wrong.

Component: Untriaged → Request Handling
Product: Firefox → WebExtensions

Hello,

I reproduced the issue on the latest Nightly (107.0a1/20220929014928), Beta (106.0b5/20220927185813) and Release (105.0.1/20220922151854) under Windows 10 x64 and Ubuntu 16.40 LTS.

The issue occurs exactly as described in the report i.e. the last shown log is “33” and there is no error logged/shown from var v = not_def_thing;.

For further details, see the attached screenshot.

Status: UNCONFIRMED → NEW
status-firefox105: --- → affected
status-firefox106: --- → affected
status-firefox107: --- → affected
Ever confirmed: true
Attached image 2022-09-29_12h25_52.png —

:ochameau, since you are the author of the regressor, bug 1675456, could you take a look? Also, could you set the severity field?

For more information, please visit auto_nag documentation.

Flags: needinfo?(poirot.alex)

Set release status flags based on info from the regressing bug 1675456

status-firefox108: --- → affected

Would you mind to run the STR in builds where the behavior was not regressed and attach a screenshot of where it was visible in the console (and what error stack trace was associated to the log entry)?

Flags: needinfo?(acornestean)

Ran the STR on Nightly 95.0a1 since this version appears to not be affected by the issue caused by the regressing bug mentioned above.

The error in question is displayed on Nightly 95. See the attached screenshot.

Flags: needinfo?(acornestean) → needinfo?(lgreco)
Attached image 2022-11-01_09h12_25.png —
Severity: -- → S4
Priority: -- → P3
Whiteboard: [addons-jira]
Assignee: nobody → lgreco
Status: NEW → ASSIGNED

I have finally managed to take a look into this and I see what is going on and what have "regressed" it:

  • for the AddonDebugging DevTools toolbox, the errors used to not be filtered at all, and so in the webconsole all errors raised in the extension process used to be visible (which means that also internal Firefox errors raised internally in that same process and errors related to other extensions running in the same process used to all be visible)

  • in bug 1675456 that is likely what changed, the errors are going being collected from a different internal DevTools module devtools/server/actors/resources/error-messages.js and they are being filtered out because the error logged here in BaseContext applySafeWithoutClone is going to:

    • have nsIScriptError innerWindowID set to 0
    • have nsIScriptError category set to "XPConnect JavaScript" (which is one of the categories associated to platform code, the browser internals, instead of third party webapps or extensions js code)

The attached patch fixes the issue by applying a few small changes to BaseContext applySafeWithoutClone to make sure we log an error with the category "content javascript" and the same innerWindowID actually associated to the BaseContext instance we are calling the listener for, plus a new test case to make sure that stays the case.

I'm clearing Alex needinfo's given that I already took a look, but I'm going to add Alex as an optional reviewer to confirm this is going to be right also from a DevTools perspective (even if both test and fix are on the WebExtensions internals side).

Flags: needinfo?(poirot.alex)
Flags: needinfo?(lgreco)
Blocks: 1810574
Blocks: 1810582

I'm tweaking the summary of this issue to better highlight that this isn't an issue just related to webRequest listeners, but actually extended to any callbacks that the extensions registers to any of the WebExtensions API events and raising an exception while handling the calls originated from the WebExtensions API events being emitted.

Summary: Extension console not logging error raised by webRequest callback function → Extension console not logging error raised by callback function handling WebExtensions API events (e.g. webRequest.onBeforeRequest, tabs.onCreated etc.)
Component: Request Handling → Developer Tools
Duplicate of this bug: 1799406
Pushed by luca.greco@alcacoop.it:
https://hg.mozilla.org/integration/autoland/rev/30d842f4406c
BaseContext applySafeWithoutClone should log errors associated to the extension page innerWindowID. r=willdurand,ochameau

(In reply to Noemi Erli[:noemi_erli] from comment #15)

Backed out changeset 30d842f4406c (Bug 1792559) for causing xpc failures in test_ext_api_events_listener_calls_exceptions.js CLOSED TREE

Push with failures: https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&collapsedPushes=842382&selectedTaskRun=clkrZfJrRdOJh5ZMgB0uRg.0&resultStatus=testfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel&revision=30d842f4406cb621b4677a72343e77785cc41dc0

Log: https://treeherder.mozilla.org/logviewer?job_id=404890303&repo=autoland&lineNumber=5745
and some mochitests: https://treeherder.mozilla.org/logviewer?job_id=404894210&repo=autoland&lineNumber=3132

Backout: https://hg.mozilla.org/integration/autoland/rev/f406f8ce5e0cf17478c3da2915da4b9c5566e7d8

I looked into this and pinpointed which was the reason behind the failure on Android builds:

  • in GeckoView builds browser.storage.sync is still using the old ExtensionStorageSyncKinto backend (Bug 1625257 is tracking the additional work to replace the old Kinto backend on GeckoView builds), while all the other builds are using the rust-based ExtensionStorageSync backend
  • while the instance of the currently enabled implementation is available through the same ExtensionParent.apiManager.global.extensionStorageSync property, the notifyListeners provided by the two implementation expected slightly different parameters:
    • ExtensionStorageSyncKinto's notifyListeners method expects the Extension class instance as its first parameter
    • ExtensionStorageSync's notifyListeners method expects the extension id instead

I've just updated the patch to account for that difference (which was a small tweak restricted only applied to the new test case included in the attached patch) and confirmed locally that the test case does pass as expected on both android and desktop builds with the small tweak applied (and that without it the test fails consistently on Android builds because the test got stuck waiting on the error expected to be raised from the storage.sync.onChanged listeners).

Flags: needinfo?(lgreco)
Pushed by luca.greco@alcacoop.it:
https://hg.mozilla.org/integration/autoland/rev/0997dafbbd86
BaseContext applySafeWithoutClone should log errors associated to the extension page innerWindowID. r=willdurand,ochameau

Backed out for causing mochitest failures on test_ext_tabs_insertCSS.html

[task 2023-02-08T01:47:06.780Z] 01:47:06  WARNING -  TEST-UNEXPECTED-FAIL | mobile/android/components/extensions/test/mochitest/test_ext_tabs_insertCSS.html | Error: Error: can't access property "Error", this is undefined ::
[task 2023-02-08T01:47:06.780Z] 01:47:06     INFO -      SimpleTest.ok@SimpleTest/SimpleTest.js:404:16
[task 2023-02-08T01:47:06.780Z] 01:47:06     INFO -      testHandler@SimpleTest/ExtensionTestUtils.js:87:18
[task 2023-02-08T01:47:06.781Z] 01:47:06     INFO -      testResult@SimpleTest/ExtensionTestUtils.js:97:18
[task 2023-02-08T01:47:06.781Z] 01:47:06     INFO -      Async*testExecuteScript@mobile/android/components/extensions/test/mochitest/test_ext_tabs_insertCSS.html:106:19
[task 2023-02-08T01:47:06.781Z] 01:47:06     INFO -      nextTick/<@SimpleTest/SimpleTest.js:2123:34
[task 2023-02-08T01:47:06.781Z] 01:47:06     INFO -      nextTick@SimpleTest/SimpleTest.js:2155:11
[task 2023-02-08T01:47:06.781Z] 01:47:06     INFO -      setTimeout handler*SimpleTest_setTimeoutShim@SimpleTest/SimpleTest.js:900:41
[task 2023-02-08T01:47:06.781Z] 01:47:06     INFO -      add_task@SimpleTest/SimpleTest.js:2072:17
[task 2023-02-08T01:47:06.781Z] 01:47:06     INFO -      @mobile/android/components/extensions/test/mochitest/test_ext_tabs_insertCSS.html:16:9
[task 2023-02-08T01:52:10.461Z] 01:52:10  WARNING -  TEST-UNEXPECTED-FAIL | mobile/android/components/extensions/test/mochitest/test_ext_tabs_insertCSS.html | Test timed out. -
[task 2023-02-08T01:52:10.461Z] 01:52:10  WARNING -  TEST-UNEXPECTED-FAIL | mobile/android/components/extensions/test/mochitest/test_ext_tabs_insertCSS.html | Extension left running at test shutdown
[task 2023-02-08T01:52:10.462Z] 01:52:10     INFO -      SimpleTest.ok@SimpleTest/SimpleTest.js:404:16
[task 2023-02-08T01:52:10.462Z] 01:52:10     INFO -      ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:132:18
[task 2023-02-08T01:52:10.462Z] 01:52:10     INFO -      executeCleanupFunction@SimpleTest/SimpleTest.js:1507:13
[task 2023-02-08T01:52:10.462Z] 01:52:10     INFO -      SimpleTest.finish@SimpleTest/SimpleTest.js:1521:3
[task 2023-02-08T01:52:10.462Z] 01:52:10     INFO -      killTest@SimpleTest/TestRunner.js:201:22
[task 2023-02-08T01:52:10.462Z] 01:52:10     INFO -      async*delayedKillTest@SimpleTest/TestRunner.js:238:17
[task 2023-02-08T01:52:10.462Z] 01:52:10     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:236:17
[task 2023-02-08T01:52:10.462Z] 01:52:10     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:249:15
[task 2023-02-08T01:52:10.462Z] 01:52:10     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:249:15
[task 2023-02-08T01:52:10.462Z] 01:52:10     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:249:15
[task 2023-02-08T01:52:10.463Z] 01:52:10     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:249:15
[task 2023-02-08T01:52:10.463Z] 01:52:10     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:249:15
[task 2023-02-08T01:52:10.463Z] 01:52:10     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:249:15
[task 2023-02-08T01:52:10.463Z] 01:52:10     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:249:15
[task 2023-02-08T01:52:10.463Z] 01:52:10     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:249:15
[task 2023-02-08T01:52:10.463Z] 01:52:10     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:249:15
[task 2023-02-08T01:52:10.463Z] 01:52:10     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:249:15
[task 2023-02-08T01:52:10.463Z] 01:52:10     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:249:15
[task 2023-02-08T01:52:10.463Z] 01:52:10     INFO -      TestRunner.runTests/<@SimpleTest/TestRunner.js:529:16
[task 2023-02-08T01:52:10.464Z] 01:52:10     INFO -      Async*TestRunner.runTests@SimpleTest/TestRunner.js:516:48
[task 2023-02-08T01:52:10.464Z] 01:52:10     INFO -      RunSet.runtests@SimpleTest/setup.js:236:14
[task 2023-02-08T01:52:10.464Z] 01:52:10     INFO -      RunSet.runall@SimpleTest/setup.js:215:12
[task 2023-02-08T01:52:10.464Z] 01:52:10     INFO -      hookupTests@SimpleTest/setup.js:312:12
[task 2023-02-08T01:52:10.464Z] 01:52:10     INFO -  parseTestManifest@http://mochi.test:8888/manifestLibrary.js:53:13
[task 2023-02-08T01:52:10.464Z] 01:52:10     INFO -  getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:66:28
[task 2023-02-08T01:52:10.464Z] 01:52:10     INFO -  EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:62:3
[task 2023-02-08T01:52:10.464Z] 01:52:10     INFO -      hookup@SimpleTest/setup.js:288:20
[task 2023-02-08T01:52:10.464Z] 01:52:10     INFO -  EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&logFile=%2Fdata%2Flocal%2Ftmp%2Ftest_root%2Flogs%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fdata%2Flocal%2Ftmp%2Ftest_root:10:1
[task 2023-02-08T01:52:10.465Z] 01:52:10     INFO -  TEST-OK | mobile/android/components/extensions/test/mochitest/test_ext_tabs_insertCSS.html | took 306494ms
Flags: needinfo?(lgreco)

I have just looked into this other failure hit on the GeckoView mochitest test_ext_tabs_insertCSS.html and it was a legit issue to be fixed in one of the changes applied to ExtensionCommon.jsm included in the patch attached to this bug (which apparently was not hit by any of the other mochitest and xpcshell tests included in my previous push to try).

I fixed that and confirmed locally that test_ext_tabs_insertCSS.html GeckoView mochitest is now passing as expected.

Pushed one more time of try to double-check I didn't miss some other failure that may be triggered by the test of the changes in the attached patch:

Flags: needinfo?(lgreco)
Pushed by luca.greco@alcacoop.it:
https://hg.mozilla.org/integration/autoland/rev/85bb9123f20c
BaseContext applySafeWithoutClone should log errors associated to the extension page innerWindowID. r=willdurand,ochameau,extension-reviewers

https://hg.mozilla.org/mozilla-central/rev/85bb9123f20c

Status: ASSIGNED → RESOLVED
Closed: 1 year ago
status-firefox111: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → 111 Branch

Verified as Fixed on the latest Nightly (111.0a1/20230208214144). Tested on Windows 10 x64 and macOS 11.3.1.

The mentioned error is now properly logged to console after the last shown log entry (“33”), confirming the fix.

For more details, see the attached screenshot.

Status: RESOLVED → VERIFIED
status-firefox111: fixed → verified

Oh no~, this bug is NOT 100% fixed.

If you change

function onBeforeRequest_main(details)

to

async function onBeforeRequest_main(details)

, the problem is still. The error message still not showing.

Fx 111.0 fixed just the "sync callback", not "async callback"

Hello garywill,

I retried the original STR from Comment 0 with the modified extension as per Comment 24 and can confirm the error message is not displayed.

The last shown log is “33” and there are no errors logged. See the attached screenshot.

Reproduced on the latest Nightly (113.0a1/20230319214532), Beta (112.0b4/20230319180129) and Release (111.0/20230309232128) under Windows 10 x64 and macOS 11.3.1.

status-firefox111: verified → ?
status-firefox112: --- → ?
status-firefox113: --- → ?

Any staff? Please reopen this bug. It's not fixed

See Also: → 1824252

(In reply to garywill from comment #24)

Oh no~, this bug is NOT 100% fixed.

If you change

function onBeforeRequest_main(details)

to

async function onBeforeRequest_main(details)

, the problem is still. The error message still not showing.

Fx 111.0 fixed just the "sync callback", not "async callback"

An async callback always return a promise, and an exception raised inside the async functions gets automatically converted into a rejected promise and returned, from the child process perspective the async function has returned successfully and so the rejection is then propagated to the parent process.

In the webRequest case, the rejected promise is handled on the parent process by WebRequest.jsm, where the rejected promise would be currently being logged in the BrowserConsole (by the catch block here in WebRequest.jsm)

I agree that it would be better to show the errors related to rejected promises got from an async listener for the API events in the AddonDebugging window, at least for the all those API events where the counterpart that is going to receive the rejected promise is part of the Firefox internals and not the extension code itself (messaging API events falls into this category instead as described in a bit more detail in Bug 1824252 comment 0), but it would be better tracked by an explicit followup.

I just filed the followup as Bug 1824252 and linked it to this bug as a seealso.

You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: