1753048 - Console logs are no longer shown in about:devtools-toolbox when debugging a web extension in Firefox 96

Status: RESOLVED FIXED

(DevTools :: about:debugging, defect, P2)

Description

[jm.gaillard]

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:95.0) Gecko/20100101 Firefox/95.0

Steps to reproduce:

On Manjaro Linux, i updated firefox through the package manager (pacman), from firefox 95.0.2 to 96.0.2.

Actual results:

After relaunch, the web extension I was working on didn't show any logs (set with console.log), in the about:devtools-toolbox console.

Expected results:

The logs should have been present in the 96 version, like in the 95 version.
Note : I downgraded Firefox to 95 version to be sure, and I can see the logs just fine, so I deduced it was the 96 version.

Comment 1

[Julian Descottes [:jdescottes]]

Thanks for logging!

Can you share more information about the missing logs?
From which script are you logging them? A background script, popup, ...?
If you can share the extension (or a simplified version of it which highlights the issue), it could also help.

Thanks

Comment 2

[Julian Descottes [:jdescottes]]

Linking to Bug 1675456, if there is a regression here, there is a high chance it comes from this.

Comment 3

[juraj.masiar]

I knew I'm not the only one!
https://discourse.mozilla.org/t/did-anyone-reported-yet-the-bug-with-background-script-console-not-updating-after-web-ext-reloads-addon/92283

I've noticed it as well, I use web-ext for development and the moment it reloads the addon, the background script console won't log any more messages - except for (some?) errors, those are still logged, but everything else is just gone.

Closing the background script tab and reopening it will fix the logging, but after another addon reload it will break again. This makes background script development extremely tedious.

Comment 4

[jm.gaillard]

Attachment: webextension.zip

Provided a simplified web extension as requested, in order to test the behavior

Comment 5

[jm.gaillard]

(In reply to Julian Descottes [:jdescottes] from comment #1)

Thanks for logging!

Can you share more information about the missing logs?
From which script are you logging them? A background script, popup, ...?
If you can share the extension (or a simplified version of it which highlights the issue), it could also help.

Thanks

Thank you for your quick response !
I just uploaded a simplified web extension, without react or babel, in order to isolate the problem.
I tested it with both firefox 95 and firefox 96. The log in index.js is shown in the former version, but not the later.
It is called from a browser_action.default_popup. I have not tested other cases, such as in a background script or in content_scripts.

Comment 6

[Julian Descottes [:jdescottes]]

Thanks for the example webextension!

Not sure yet where this comes from, because it is very similar to one of our tests: https://searchfox.org/mozilla-central/source/devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_addons_debug_console.js

It seems that when no background script is defined for the extension, we don't capture any log and I can see many exceptions in our stdout:

console.warn: "Failed to add session data entry for frame targets in browsing context" 48
console.warn: (new Error("No target actor for this Watcher Actor ID:\"server0.conn1.watcher46\" / BrowserId:undefined", "resource://devtools/server/connectors/js-window-actor/DevToolsFrameChild.jsm", 552))

As soon as I add a background script, even if the script is an empty file, then logs start to work.

Can you confirm if your original extension also doesn't use any background script, to make sure we are investigating the right problem.

Comment 7

[jm.gaillard]

(In reply to Julian Descottes [:jdescottes] from comment #6)

Thanks for the example webextension!

Not sure yet where this comes from, because it is very similar to one of our tests: https://searchfox.org/mozilla-central/source/devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_addons_debug_console.js

It seems that when no background script is defined for the extension, we don't capture any log and I can see many exceptions in our stdout:

console.warn: "Failed to add session data entry for frame targets in browsing context" 48
console.warn: (new Error("No target actor for this Watcher Actor ID:\"server0.conn1.watcher46\" / BrowserId:undefined", "resource://devtools/server/connectors/js-window-actor/DevToolsFrameChild.jsm", 552))

As soon as I add a background script, even if the script is an empty file, then logs start to work.

Can you confirm if your original extension also doesn't use any background script, to make sure we are investigating the right problem.

I can confirm : my original extension doesn't use any background script, as of yet.

Also, i tested the behavior you described, by adding a background script to the simplified webextension I sent you, and had the same result : the logs started working.

So I think you are indeed investigating the right problem.

Comment 8

[BugBot [:suhaib / :marco/ :calixte]]

The severity field is not set for this bug.
:jdescottes, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 9

[juraj.masiar]

I have some easy steps to reproduce in any addon that has background page:

1. open background script console of any addon, for example uBlock origin:

about:devtools-toolbox?id=uBlock0%40raymondhill.net&type=extension

2. execute browser.runtime.reload()
3. execute browser.runtime.reload()
   This time it won't reload the console anymore, the console is already broken after the first reload.

Comment 10

[Tomislav Jovanovic :zombie]

Hey Julian, any luck with this? Anything the Web Extensions team can help with? We've heard developers are worried this might be an issue for the another whole year if the fix doesn't make it in the next ESR.

Comment 11

[Julian Descottes [:jdescottes]]

Sorry, this fell off my radar, I'll pick this back up today. Thanks for the reminder.

Comment 12

[Julian Descottes [:jdescottes]]

Quick summary of the issue.

When we add a background page to example webextension from comment #4, the toolbox starts on the "_generated_background_page.html" page, which is considered as a valid window global target for this toolbox. Which means that we correctly setup all our resource watchers for it.

When you trigger the popup, the additional target (for /public/index.html in the provided example extension) becomes available in the iframe dropdown, and the console will shows the expected console messages. You can open and close the popup several times, the console will just show all the messages.

Back to the initial example webextension, without any background script. In this case, we have no default page for the extension to use as a valid target. In this case we use a "fallback window", created for devtools needs only here. However the principal related to this window will not be populated with the addonId from the extension. Which we use in our filtering mechanism here. Which means the target associated to the fallback window will not be considered as valid to start watching for console messages etc...

Locally, I added a simple workaround to insert the addonId information in the URL of the fallback window and used that in the filter. That seems to fix the issue, console logs now start showing up. That's maybe not the best approach. If we could properly set the addonId in the principal it might be better. But I'm confident we can quickly come up with a good fix and uplift it.

Sidenote: the workflow in this setup is not ideal. Basically everytime you open the popup, the toolbox will "navigate" between the fallback window and the popup's window, which cleans the console unless you have enabled persist logs. The fallback window mechanism is mostly a workaround so that devtools always has a valid windowglobal target available, but we are looking at improving UX around this kind of scenarios.

Comment 13

[Julian Descottes [:jdescottes]]

Attachment: Bug 1753048 - [devtools] Append the addonId to the DevTools fallback window URL

The fix is just a WIP, at least the test might be useful

Comment 14

[Julian Descottes [:jdescottes]]

Attachment: Bug 1753048 - Serve the webextension fallback window from moz-extension

We currently serve the webextension fallback window page via a chrome URL, and the corresponding global does not have the extension principal.
Serving the fallback window from a moz-extension URL fixes this. This is similar to how we handle the generated background page.

This will allow devtools to sanely check the principal addonId in order to identify globals that should be debugged for a given extension.

Comment 15

[Julian Descottes [:jdescottes]]

Attachment: Bug 1753048 - [devtools] Include the fallback window to the docShells array for webextension targets

Depends on D148489

This allows to properly set the cssErrorReportingEnabled flag on its docShell.
While we are not interested in css errors for this fallback window, the windowglobal target actor
will automatically set the flag on new root browsing contexts only if the previous one had the flag
set. This way when we switch to a valid webextension document (eg a popup), the flag will be set
and CSS errors will be reported.

Comment 16

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/845c0d85f221
[devtools] Append the addonId to the DevTools fallback window URL r=ochameau
https://hg.mozilla.org/integration/autoland/rev/5092df1913d5
[devtools] Include the fallback window to the docShells array for webextension targets r=ochameau

Comment 17

[Julian Descottes [:jdescottes]]

Comment on attachment 9280009 [details]
Bug 1753048 - [devtools] Append the addonId to the DevTools fallback window URL

Beta/Release Uplift Approval Request

• User impact if declined: Extension developers cannot see console.logs when debugging extensions. This does not affect all extensions. In particular, extensions defining a background script happen to work (which is why the bug was undetected in the first place). But that still affects many developers and considering that 102 will be an ESR version, it would be great to make sure that developers can test their extensions against ESR 102 correctly
• Is this code covered by automated tests?: Yes
• Has the fix been verified in Nightly?: No
• Needs manual test from QE?: No
• If yes, steps to reproduce:
• List of other uplifts needed: None
• Risk to taking this patch: Low
• Why is the change risky/not risky? (and alternatives if risky): Simple javascript fix, devtools only.
• String changes made/needed:
• Is Android affected?: No

Comment 18

[Cristian Tuns]

https://hg.mozilla.org/mozilla-central/rev/845c0d85f221
https://hg.mozilla.org/mozilla-central/rev/5092df1913d5

Comment 19

[Pascal Chevrel:pascalc (PTO until April 26)]

Comment on attachment 9280009 [details]
Bug 1753048 - [devtools] Append the addonId to the DevTools fallback window URL

Approved for our last 102 beta, thanks.

Comment 20

[Pascal Chevrel:pascalc (PTO until April 26)]

https://hg.mozilla.org/releases/mozilla-beta/rev/5c712672d2d2
https://hg.mozilla.org/releases/mozilla-beta/rev/922dc4e167b7