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.

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.

Regression window:
https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=7a8280c92ccd172f5637f1ed12343610e275e019&tochange=162a9da3f9b2cb778d23e199655a9603c9d37cbb

: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.

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

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)?

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.

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).

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.

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

(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).

Backed out for causing mochitest failures on test_ext_tabs_insertCSS.html

• backout: https://hg.mozilla.org/integration/autoland/rev/3bc8f155649d5e5eaaed0c63f5d166eeeedfe3f4
• push: https://treeherder.mozilla.org/jobs?repo=autoland&revision=0997dafbbd86494aeff66252b87946c2d6158641
• failure log: https://treeherder.mozilla.org/logviewer?job_id=404955129&repo=autoland&lineNumber=4119

[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

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:

• https://treeherder.mozilla.org/jobs?repo=try&revision=d600b281e7374f5f0fe1b611c20a10c64d6bc54f

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

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.

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.

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

(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.