1547643 - Missing console.log() entries from runner.js in Firefox and Chrome dev tools console

Status: NEW

(Testing :: Raptor, defect, P3)

Description

[Henrik Skupin [:whimboo][⌚️UTC+1]]

I'm trying to debug a Raptor test when running under Chrome but any call to console.log() inside of runner.js doesn't cause an entry listed in the console view of the dev tools. It's all fine for page_log.js.

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+1]]

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from bug 1550430 comment #4)

Something interesting I found is that when calling console.log() in the global scope of the background script (and the window hasn't been loaded yet), there is no browser console entry visible. Maybe this is a bug in the console logging API? Andrew, do you know?

Andrew, any idea why this is happening? It also happens for Chrome, so maybe it is an expected behavior?

Comment 2

[Andrew Swan [:aswan]]

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #1)

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from bug 1550430 comment #4)

Something interesting I found is that when calling console.log() in the global scope of the background script (and the window hasn't been loaded yet), there is no browser console entry visible. Maybe this is a bug in the console logging API? Andrew, do you know?

Andrew, any idea why this is happening? It also happens for Chrome, so maybe it is an expected behavior?

I'm not really sure what you're asking. I don't know what runner.js or page_log.js are, and I'm not sure which window you're referring to in the comment above...
Perhaps you could create a simplified test case that illustrates the scenario you're looking at?

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Sorry, so runner.js is a background script of the Raptor web extension which can be found at:
https://searchfox.org/mozilla-central/source/testing/raptor/webext/raptor

Of interest are those lines at the very end of the file:
https://searchfox.org/mozilla-central/rev/ddb81c7a43ffada1f6cb4200c4f625e50e44dcf3/testing/raptor/webext/raptor/runner.js#657-662

When I change the postToControlServer() calls to console.log() those entries do not appear in the browser console. But it starts working when the registered listener for the load event is getting executed. As such it looks like that the console API is not able to to post something to the browser console until the internal window(?) of the background script has been fully loaded.

To check that yourself you could modify those lines, and then run the following command:

$ ./mach raptor-test --test=raptor-tp6-1

I hope that explanation helps. If you are the wrong person I appreciate if you could move the needinfo forward. Thanks.

Comment 4

[Andrew Swan [:aswan]]

I have no idea. The extension framework doesn't do anything special here, console is a regular DOM api implemented at the platform level.
Or perhaps there's an issue with the browser console getting messages from the extension process relatively early in its lifetime.

This is a shot in the dark but lets see if somebody from devtools has any input.

Comment 5

[Nicolas Chevobbe [:nchevobbe]]

Hello Henrik,

I did some investigation and I think I know what's going wrong.
So, there's nothing special with the console api here, once the Browser Console is open, we get all the messages.
For example, if you apply the following to runner.js:

diff --git a/testing/raptor/webext/raptor/runner.js b/testing/raptor/webext/raptor/runner.js
--- a/testing/raptor/webext/raptor/runner.js
+++ b/testing/raptor/webext/raptor/runner.js
@@ -654,9 +654,10 @@ function raptorRunner() {
   });
 }
 
-if (window.addEventListener) {
-  window.addEventListener("load", raptorRunner);
-  postToControlServer("status", "Attaching event listener successful!");
-} else {
-  postToControlServer("status", "Attaching event listener failed!");
-}
+Promise.all([
+  new Promise(res => setTimeout(res, 20000)),
+  new Promise(res => window.addEventListener("load", res)),
+]).then(() => {
+  console.info("🦊", "window loaded");
+  raptorRunner();
+});

i.e. waiting for the load event and 20s (which gives you enough time to open the browser console), I do see the 🦊 window loaded message.

---

So it looks like the issue is that the Browser Console does not get cached messages.
That's not extension related, if you start Firefox without the browser console, then do a console.log in a content page, and after that, open the Browser Console, you won't see the log message.

In order for the Browser Console to show content messages (and webextension ones), we pipe content process messages to the relevant one (https://searchfox.org/mozilla-central/source/devtools/server/actors/webconsole/content-process-forward.js).

But when we open the Browser Console, and retrieve cached messages, we don't get content process cached messages. Which explains what you are seeing.

A workaround is to use aboutdebugging (opening a about:devtools-toolbox?type=extension&id=raptor%40mozilla.org tab should work, or go to about:debugging#/runtime/this-firefox and click Inspect in the Raptor section. You can then get access to the console, with all the messages (I guess you could even create such tab from runner.js so you don't have to jump through hoops every time).

Hope this is useful!

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Ok, that sounds plausible and I can see those entries now. But is that also the reason that no console API calls are getting forwarded to stdout even with the following two preferences set?

user_pref("devtools.console.stdout.chrome", true);
user_pref("devtools.console.stdout.content", true);

When calling eg. console.log() from within a content script I don't see any of those entries in stdout, but only in the browser console. For Raptor we would really like to get all the console API calls for log(), info(), warn(), and error() forwarded to stdout for logging purposes. Why does that only work for background but not content scripts?

Comment 7

[Nicolas Chevobbe [:nchevobbe]]

I don't think the cache bug should have any effect on stdout printing.
I just tested it running ./mach run --devtools --setpref devtools.console.stdout.content=true , going to a test page which emits console.* calls and everything appear in the terminal as it should.
But I do reproduce what you see in the raptor test.

Baku, are we waiting on anything specific before logging console api calls to stdout?

Comment 8

[Andrea Marchesini [:baku]]

No, if the prefs are set to true, console API writes to stdout immediately. Note that the console API can be disabled in case devtools.enabled is set to false or in case the global is not chrome:
https://searchfox.org/mozilla-central/rev/f8b11433159cbc9cc80500b3e579d767473fa539/dom/console/Console.cpp#1224-1231