Closed Bug 1410932 Opened 7 years ago Closed 2 years ago

Errors raised in the content scripts context should be logged in the related tab's webconsole

Categories

(WebExtensions :: Developer Tools, defect, P3)

defect

Tracking

(firefox110 fixed)

RESOLVED FIXED
110 Branch
Tracking Status
firefox110 --- fixed

People

(Reporter: rpl, Assigned: ochameau)

References

(Blocks 3 open bugs)

Details

(Whiteboard: [addon-debugging] [platform-rel-Wikipedia] )

Attachments

(5 files, 5 obsolete files)

59 bytes, text/x-review-board-request
Details
59 bytes, text/x-review-board-request
Details
59 bytes, text/x-review-board-request
Details
48 bytes, text/x-phabricator-request
Details | Review
48 bytes, text/x-phabricator-request
Details | Review
Currently the Errors raised in a content script (as well as js code or urls executed in the content script context using tabs.executeScript) are reported to the console service without the expected innerWindowID, which should be the innerWindowID of the webpage that the content script is associated to, so that these errors can be detected by the tab webconsole. The goal of this issue is to: - ensure that when we are directly handling exception raised and promise rejected by code running in the content script context, we also associate them to the expected innerWindowID when reported (e.g. errors raised when we are executing the js code or url in http://searchfox.org/mozilla-central/source/toolkit/components/extensions/ExtensionContent.jsm#356-362, but also when the error is raised from inside a API event listener, like in `browser.runtime.onMessage.addListener(() => throw new Error(...));`) - ensure that any unhandled errors and uncaught exception from a content script context will be associated to the related webpage (e.g. errors raised from inside a listener subscribed by the content script to a DOM event or inside a Promise chain created inside the content script)
Assignee: nobody → lgreco
Blocks: 1401241, 1319048
Status: NEW → ASSIGNED
Priority: -- → P3
I'm still working on making sure that the errors reported from inside an API event listener and an API methods callback are going to be reported with the expected innerWindowID, but In the meantime I've attached the set of the preliminary patches so that it will be simpler to ask a feedback and discuss the proposed strategies.
Comment on attachment 8921109 [details] Bug 1410932 - Log in the tab webconsole content script errors caught while executing. Hi Kris, this patch contains a proposed change needed to ensure that when we report the errors raised when executing a content scripts in the content script sandbox, we associate the error to the related window innerWindowID (so that the error will be recognized as one of the errors to show in the Tab's DevTools webconsole panel). The tests related to this scenario (as well as the errors related to uncaught errors, e.g. the one raised from a callback subscribed to a DOM event, and unhandled rejections, e.g. raised in a promise chain created by the content script) are in the patch related to this mozreview url: https://reviewboard.mozilla.org/r/192086/diff/#index_header
Attachment #8921109 - Flags: feedback?(kmaglione+bmo)
Comment on attachment 8921111 [details] Bug 1410932 - AutoJS::ReportException should report Content Script errors on the related DOM Window. Hi Kris, It looks that xpc::IsAddonCompartment should recognize the content script sandboxes as an addon compartment but it currently doesn't, this patch contains a proposed change so that it is going to recognize the content script sandboxes correctly. The tests related to this scenario: errors related to uncaught errors, e.g. the one raised from a callback subscribed to a DOM event are part of the patch at the following mozreview url: https://reviewboard.mozilla.org/r/192086/diff/#index_header
Attachment #8921111 - Flags: feedback?(kmaglione+bmo)
Comment on attachment 8921112 [details] Bug 1410932 - Promise::ReportRejectedPromise should report Content Script unhandled rejection on the related DOM Window. Hi Boris, in AutoJSAPI::ReportException we currently try to determine which is the innerWindowID that we should report the exception for by also looking at the addon sandboxes (http://searchfox.org/mozilla-central/rev/1ebd2eff44617df3b82eea7d2f3ca1b60cc591a0/dom/script/ScriptSettings.cpp#595-600) It seems that it currently fails to detect the WebExtensions content script as an Addon scope (and that is what the proposed change in attachment 8921111 [details] aims to fix), but besides that fix it seems that to be able to associate the unhandled rejections coming from a WebExtensions content script, we should also apply to Promise::ReportRejectedPromise a change similar to what AutoJSAPI::ReportException is doing in the fragment linked above. While Kris is helping me to evaluate the other changes in this mozreview, I'd like to ask you an initial feedback on this scenario (and the proposed change from this patch).
Attachment #8921112 - Flags: feedback?(bzbarsky)
Comment on attachment 8921110 [details] Bug 1410932 - Errors raised by executing jsCode with tabs.executeScripts should not have ExtensionContent.jsm has their url. Hi Jason, When an WebExtension add-on uses browser.tab.executeScript, it can use both a moz-extension url or a string which contains the JS code to execute in the content script sandbox. Unfortunately if we don't specify an url in the Cu.evalInSandbox call, the errors reported from it are going to be wrongly associated to the ExtensionContent.jsm url. In this patch I'm proposing to set that url to a custom url (which is not a moz-extension:// url because there isn't a real url that we can use to retrieve something from, and so it is a fake url that we can use to recognize it, and also be able to know which extension is it coming from if we need to in other follow ups). This is only a piece of a group of changes needed to make sure that the content script errors are reported in the tab's DevTools webconsole and that a user is going to be able to click on the url reported in the webconsole to see the actual code that raises the error in the debugger panel, and then to be able to set a breakpoint on it etc.) Do you mind to take a brief look for an initial feedback?
Attachment #8921110 - Flags: feedback?(jlaster)
Comment on attachment 8921112 [details] Bug 1410932 - Promise::ReportRejectedPromise should report Content Script unhandled rejection on the related DOM Window. https://reviewboard.mozilla.org/r/192084/#review199626 ::: dom/promise/Promise.cpp:505 (Diff revision 1) > - nsGlobalWindow* win = isMainThread ? xpc::WindowGlobalOrNull(aPromise) : nullptr; > + > + nsGlobalWindow* win; > + > + // If the promise is coming from a AddonScope (e.g. a WebExtensions Content Script), > + // get the window related to the content script sandbox global. > + if (xpc::IsInAddonScope(aPromise)) { I don't think you need the IsInAddonScope check, right? You can just use the pattern we use everywhere else, where we do WindowGlobalOrNull and if that returns null call AddonWindowOrNull. In fact, maybe we should have a helper function for that pattern...
Attachment #8921112 - Flags: review+
Comment on attachment 8921111 [details] Bug 1410932 - AutoJS::ReportException should report Content Script errors on the related DOM Window. This function is meant to have a 1:1 correspondence with the isAddonCompartment flag. Its existing callers depend on that. If you want to check the isWebExtensionContentScript flag too, you'll need to add another getter function.
Attachment #8921111 - Flags: feedback?(kmaglione+bmo) → feedback-
Comment on attachment 8921112 [details] Bug 1410932 - Promise::ReportRejectedPromise should report Content Script unhandled rejection on the related DOM Window. https://reviewboard.mozilla.org/r/192084/#review199834 ::: dom/promise/Promise.cpp:506 (Diff revision 1) > + nsGlobalWindow* win; > + > + // If the promise is coming from a AddonScope (e.g. a WebExtensions Content Script), > + // get the window related to the content script sandbox global. > + if (xpc::IsInAddonScope(aPromise)) { > + win = isMainThread ? xpc::AddonWindowOrNull(aPromise) : nullptr; AddonWindowOrNull is specifically meant to deal with compartment-per-addon Sandboxes, which apply to chrome-privileged add-on contexts, and have different semantics from content script sandboxes. I'm not comfortable overloading it this way.
Comment on attachment 8921109 [details] Bug 1410932 - Log in the tab webconsole content script errors caught while executing. https://reviewboard.mozilla.org/r/192078/#review199836 ::: toolkit/components/extensions/ExtensionContent.jsm:28 (Diff revision 1) > +XPCOMUtils.defineLazyGetter(this, "consoleService", () => { > + return Cc["@mozilla.org/consoleservice;1"].getService(Ci.nsIConsoleService); > +}); Please just use `Services.console` ::: toolkit/components/extensions/ExtensionContent.jsm:361 (Diff revision 1) > + try { > - result = script.executeInGlobal(context.cloneScope); > + result = script.executeInGlobal(context.cloneScope); > + } catch (err) { > + context.reportError(err); > + } > } > > if (this.matcher.jsCode) { > + try { > - result = Cu.evalInSandbox(this.matcher.jsCode, context.cloneScope, "latest"); > + result = Cu.evalInSandbox(this.matcher.jsCode, context.cloneScope, "latest"); > + } catch (err) { > + context.reportError(err); > + } For scripts executed by `executeScript`, these errors need to be propagated to the caller. If you want to use different reporting behavior for static content scripts, you need to handle catching those exceptions in the caller. ::: toolkit/components/extensions/ExtensionContent.jsm:533 (Diff revision 1) > Cu.nukeSandbox(this.sandbox); > this.sandbox = null; > } > + > + reportError(err) { > + let scriptError = Cc["@mozilla.org/scripterror;1"].createInstance(Ci.nsIScriptError); Please use `Components.Constructor` for this. ::: toolkit/components/extensions/ExtensionContent.jsm:540 (Diff revision 1) > + windowId = this.contentWindow.QueryInterface(Ci.nsIInterfaceRequestor) > + .getInterface(Ci.nsIDOMWindowUtils) > + .currentInnerWindowID; Please use ExtensionUtils.getInnerWindowID for this. ::: toolkit/components/extensions/ExtensionContent.jsm:546 (Diff revision 1) > + .getInterface(Ci.nsIDOMWindowUtils) > + .currentInnerWindowID; > + } > + > + const details = { > + name: err && err.name || "UnknownError", No need for the `err &&`, and the fallback to "UnknownError" is a bit strange.
Attachment #8921109 - Flags: feedback?(kmaglione+bmo) → feedback+
Attachment #8921112 - Flags: feedback?(bzbarsky) → feedback+
Comment on attachment 8921110 [details] Bug 1410932 - Errors raised by executing jsCode with tabs.executeScripts should not have ExtensionContent.jsm has their url. https://reviewboard.mozilla.org/r/192080/#review202282 It would be nice to have a test for this case.
Attachment #8921110 - Flags: review+
(In reply to Jason Laster [:jlast] from comment #17) > Comment on attachment 8921110 [details] > Bug 1410932 - Errors raised by executing jsCode with tabs.executeScripts > should not have ExtensionContent.jsm has their url. > > https://reviewboard.mozilla.org/r/192080/#review202282 > > It would be nice to have a test for this case. Absolutely, I wanted to get your feedback on the proposed approach as a first step, while I'm looking into the other pieces with Kris and Boris help, but I'm not going to land that change without a new test case for it.
Comment on attachment 8921109 [details] Bug 1410932 - Log in the tab webconsole content script errors caught while executing. https://reviewboard.mozilla.org/r/192078/#review199836 > For scripts executed by `executeScript`, these errors need to be propagated to the caller. If you want to use different reporting behavior for static content scripts, you need to handle catching those exceptions in the caller. yeah, that's true, I opted to re-throw the exception from the try...catch (the main reason is that I think that it would be better to ensure that error that we are going to report in the tab webconsole is coming from the content script execution and not any other exception that can have been raised from the WebExtensions internals that are part of the process of executing a content script).
Comment on attachment 8921112 [details] Bug 1410932 - Promise::ReportRejectedPromise should report Content Script unhandled rejection on the related DOM Window. https://reviewboard.mozilla.org/r/192084/#review199626 > I don't think you need the IsInAddonScope check, right? You can just use the pattern we use everywhere else, where we do WindowGlobalOrNull and if that returns null call AddonWindowOrNull. > > In fact, maybe we should have a helper function for that pattern... Yeah, I agree, IsInAddonScope (or the new IsInContentScriptScope) doesn't seem to be needed here. I agree on the helper function, and I was also tempted to turn the above fallback pattern into an helper function, but there are some small differences that made me opt to defer to propose such helper function, until I am sure that I have a complete picture of the scenarios and I'm not missing some important difference. (e.g. in the attachment 8921111 [details] patch, while I was applying the changes suggested by Kris, I noticed that for the errors related to a Content Script we don't want to notify the listeners subscribed to the webpage's window "error" event, or an error raised in a content script will leak the extension url to the webpage).
Comment on attachment 8921112 [details] Bug 1410932 - Promise::ReportRejectedPromise should report Content Script unhandled rejection on the related DOM Window. https://reviewboard.mozilla.org/r/192084/#review199834 > AddonWindowOrNull is specifically meant to deal with compartment-per-addon Sandboxes, which apply to chrome-privileged add-on contexts, and have different semantics from content script sandboxes. I'm not comfortable overloading it this way. I've updated this patch to use the new xpc::ContentScriptWindowOrNull helper.
Comment on attachment 8921111 [details] Bug 1410932 - AutoJS::ReportException should report Content Script errors on the related DOM Window. Hi Kris, as you suggested (and I can add "wisely" for the reason described below and in Comment 26) I've updated this patch to define new helper functions for the WebExtensions Content Scripts, and as I briefly described in Comment 26 I also noticed that we don't want the content script errors to be notified to the webpage's error listeners (which is different from what we wanted for the privileged Addon scopes). Could you take a brief look at the new version to confirm me if I'm on the right path and I can proceed to complete the rest changes? (in particular adding the test cases that are not yet included in this set of patches). Thanks again for the previous round of comments.
Attachment #8921111 - Flags: feedback?(kmaglione+bmo)
See Also: → 1423449
Product: Toolkit → WebExtensions
See Also: → 1477320
Assignee: lgreco → nobody
Status: ASSIGNED → NEW
Type: enhancement → defect
Whiteboard: [addon-debugging]
Comment on attachment 8921111 [details] Bug 1410932 - AutoJS::ReportException should report Content Script errors on the related DOM Window. Clear old feedback request, not needed anymore (because the patch is for sure outdated now).
Attachment #8921111 - Flags: feedback?(kmaglione+bmo)
See Also: → 1433543

I think I am going to resurrect at least the patch in "Bug 1410932 - AutoJS::ReportException should report Content Script errors on the related DOM Window. ". That should cover a rather large amount of existing cases.

(In reply to Tom Schuster [:evilpie] from comment #32)

I think I am going to resurrect at least the patch in "Bug 1410932 - AutoJS::ReportException should report Content Script errors on the related DOM Window. ". That should cover a rather large amount of existing cases.

That would be great! Please feel free to steal the patch and change it as appropriate.

I might not get to this immediately, but I don't want to forget about it.

Assignee: nobody → evilpies

I rebased this patch, but I think the approach is not great. Something like throw "abc"; breaks it. It would be a lot better if this was actually handled by AutoJSAPI::ReportException. I need to find out why that code is not used in this specific case.

(In reply to Tom Schuster [:evilpie] from comment #37)

I rebased this patch, but I think the approach is not great. Something like throw "abc"; breaks it. It would be a lot better if this was actually handled by AutoJSAPI::ReportException. I need to find out why that code is not used in this specific case.

yeah, I totally agree, changing AutoJSAPI::ReportException would be way better and it should be easy enough.

e.g. we could likely check here in AutoJSAPI::ReportException if the exception is coming from the script sandbox and report the error as coming from the inner window id of the window we set as the sandboxPrototype.

how that sounds to you?

Flags: needinfo?(evilpies)

Yes that would basically be step two. Right now AutoJSAPI::ReportException isn't invoked at all, we also need to fix mozilla::dom::Promise::ReportRejectedPromise which is used instead when doing evalInSandbox. We can probably use the same fix in both places.

Flags: needinfo?(evilpies)
Attachment #9138981 - Attachment is obsolete: true
Attachment #8921109 - Attachment is obsolete: true

I just submitted my approach for this. Right now we execute code through inject in ExtensionContent.jsm. Because that is an async function at some point we will run Promise::ReportRejectedPromise if executing e.g. evalInSandbox threw an exception. This however means that the Promise is allocated in the BackstagePass global used to run the jsm. To find out the "correct" innerWindowID we look at the rejection value's global. This however only works if we threw some object, instead of a value like throw "abc";. So this is sort-of a hack, but it does get is most of the way with very few changes in other code.

Attachment #8921111 - Attachment is obsolete: true
Attachment #8921112 - Attachment is obsolete: true

I updated the patch by using AutoEntryScript in executeInGlobal. This will report the pending exception when leaving the block containing the execute call. However this also means that executeInGlobal now is infallible and doesn't propagate the error to the outside. I would need to make a similar change in evalInSandbox.

I still feel like there must be a better way to do this :(

Assignee: evilpies → nobody
Attachment #9139202 - Attachment is obsolete: true

In bug 1696756 I added code to log uncaught promise rejections from content-scripts to the Webconsole.

Depends on: 1696756
Whiteboard: [addon-debugging] → [addon-debugging] [platform-rel-Wikipedia]

Ran into this during development of the WikimediaDebug extension. There was an uncaught error in first line of a sendMessage callback in content_script.js, and this was not in any way accessible in DevTools.

Not via the "Inspect" context for the extension (which inspects the background.js process, as I understand it). And not via the main devtools console for one of the browser tabs.

I note that in Chrome these are reported to the console by default, and that if you try/catch the callback in its entirety that then calls console.log(error), it does show up, so general tracing and console messages do make their way through it seems.

Downstream issue: https://phabricator.wikimedia.org/T294335 (went unnoticed because it was only detectable in Chrome).

I always forget about this bug and then after trying everything and spending so much time debugging it I remember I should try to open it in Chrome and suddenly the console is full of errors...
I would really make content script development so much better if stupid mistakes were easy to spot :(

Bitten and lost much time as well. This makes for quite an unpleasant developer experience when working on WebExtensions.

I chased my tail assuming this was a React bug since it reported "The above error occurred..." when there was no actual exception reported above. Anecdotally, it doesn't look like everything gets to the Browser Console either.

The way I've been able to debug my content script is using "Pausing on exceptions" (which isn't always practical) and explicit debugger statements.

Same thing. I don't know how many times I've fallen into this bug trap. It makes developing with FF quite the chore, if your scripts silently die, you then waste half an hour to remember that FF doesn't show the errors, then you track down the offending line with countless "logs" and then you finally have to guess what the error in that line could actually be.
This bug has been reported 5 years ago and still has the status "NEW".

omg, I wish ff has bug sponsoring program, I could donate a bit for it been fixed.

So bug 1696756 fixed error report for all async code, like:

setTimeout(()=> throw Error("foo"));

(async () => {
  throw Error("foo");
})();

Promise.reject("foo");

But, synchronous errors are still an issue.
What happens is that we evaluate the content script over there:
https://searchfox.org/mozilla-central/rev/9769b513e38ee4f5df9d5d1eff55ff7cdc8cbf81/toolkit/components/extensions/ExtensionContent.jsm#578-597

    try {
      for (let script of scripts) {
        result = script.executeInGlobal(context.cloneScope); // <<========= THIS WILL THROW
      }

      if (this.matcher.jsCode) {
        result = Cu.evalInSandbox(
          this.matcher.jsCode,
          context.cloneScope,
          "latest",
          "sandbox eval code",
          1
        );
      }
    } finally {
      lazy.ExtensionTelemetry.contentScriptInjection.stopwatchFinish(
        extension,
        context
      );
    }

executeInGlobal will throw. The try/finally won't handle the exception.
The exception will be considered as unhandled and will be processed by the following code:
https://searchfox.org/mozilla-central/rev/9769b513e38ee4f5df9d5d1eff55ff7cdc8cbf81/dom/promise/Promise.cpp#582-602

    if (nsGlobalWindowInner* win = xpc::WindowGlobalOrNull(aPromise)) {
      winForDispatch = win;
      innerWindowID = win->WindowID();
    } else if (nsGlobalWindowInner* win = xpc::SandboxWindowOrNull(
                   JS::GetNonCCWObjectGlobal(aPromise), aCx)) {
      // Don't dispatch rejections from the sandbox to the associated DOM
      // window.
      innerWindowID = win->WindowID();
    }

This is interesting as that's the new code introduced by bug 1696756, which fixes all promises created within the content script.
From there, unless we try to lookup for the original exception object's global, there isn't much we can do.

We should probably be doing something similar to comment 42.
It should probably be up to PrecompiledScript::executeInGlobal to be throwing the exception right to the console with the right innerWindowID.

Assignee: nobody → poirot.alex

The attached patch is a rebase'n polished version of Tom's, with additional tests https://phabricator.services.mozilla.com/D70211

I made it so that executeInGlobal still throws when the content script throws.
So that we get two distinct error messages. One in the web console and another one in the browser console.
Now, I'm not really used to Spidermonkey codebase. I don't know what are the real consequences of using AutoEntryScript vs AutoRealm.
But I know that we want something exactly like its ReportException method:
https://searchfox.org/mozilla-central/rev/9769b513e38ee4f5df9d5d1eff55ff7cdc8cbf81/dom/script/ScriptSettings.cpp#480-557

While testing the first patch, I realized that syntax errors were following a completely different codepath, via ChromeUtils.compileScript.
Now, in compileScript, there isn't much we can do to relate the exception to the web page.
It sounds like we ought to do something from ExtensionContent.inject and manually notify the web console.
I pushed another patch in that direction.

Similar bug on webRequest callback Extension console not logging error raised by webRequest callback function.
Not just content script.

Severity: normal → S3

For anyone who, like me, opened the Browser Console with Ctrl+Shift+J, and still didn't see any error messages there:

You have to switch the Browser Console Mode from "Parent process only" to "Multiprocess". Only there did I start seeing error messages from my content script (and also logs of event handlers of background script).

On Ubuntu Linux, I see the switch as a radio selector at the top of the browser console window.

The severity field for this bug is relatively low, S3. However, the bug has 5 duplicates.
:ochameau, could you consider increasing the bug severity?

For more information, please visit auto_nag documentation.

Flags: needinfo?(poirot.alex)

The last needinfo from me was triggered in error by recent activity on the bug. I'm clearing the needinfo since this is a very old bug and I don't know if it's still relevant.

Flags: needinfo?(poirot.alex)

Hey Kris,
would you mind to give the attached reviews another review pass? or if you are too busy at the moment, could you suggest us other peers that may take over the last review pass on the chrome-webidl and js/xpconnect parts of D157334?

Tomislav offered to cover the parts of the two reviews that can be reviewed and signed off from a WebExtensions peer.

Flags: needinfo?(kmaglione+bmo)
Pushed by apoirot@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/91fcd1c0472a Set innerWindowID for exception coming from WebExtension content scripts. r=kmag https://hg.mozilla.org/integration/autoland/rev/8ef94baa9816 Log message to the web console in case of content script syntax errors. r=kmag,zombie
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → 110 Branch
Blocks: 1805492
Flags: needinfo?(kmaglione+bmo)
Regressions: 1805328
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: