1480544 - Add a new pref for printing content console.log to stdout (devtools.console.stdout.content)

Status: RESOLVED FIXED

(DevTools :: Console, enhancement, P2)

Description

[Richard Newman [:rnewman]]

As far as I can tell the only way to get web content output to appear in stdout is for:

1. browser.dom.window.dump.enabled to be set to true, and
2. The page to do something like

```
console.log = (x) => { window.dump("" + x + "\n"); };
```

That's a bit hacky, it doesn't work if you don't control the page, and it doesn't behave exactly like the console (e.g., objects aren't JSONified).

Chrome's behavior here is to log the console to stdout if verbose logging is enabled.

I think it makes sense to have either the dump pref also apply to console.log, or to have an additional pref or command-line argument available.

bgrins kindly pointed me to the appropriate line in Console.cpp:

https://searchfox.org/mozilla-central/source/dom/console/Console.cpp#1093

This bug seems related to Bug 1439686.

Comment 1

[Dylan Hardison [:dylan] (he/him)]

Out of curiosity, is there any filtering done?
e.g. can a malicious page output something containing terminal escape codes?

Comment 2

[Brian Grinstead [:bgrins]]

(In reply to Dylan Hardison [:dylan] (he/him) from comment #1)
> Out of curiosity, is there any filtering done?
> e.g. can a malicious page output something containing terminal escape codes?

Not sure - forwarding the question to :baku. Also unsure if we use the same mechanism for printing out console log messages as we do for `window.dump` (which is already web-exposed, but only works when the pref is flipped).

Comment 3

[Andrea Marchesini [:baku]]

Attachment: console.patch

Yes, I don't see any valid reason to support writing on stdout for dump() and not for console.log().

Comment 4

[Eric Rahm [:erahm]]

Comment on attachment 8997430 [details] [diff] [review]
console.patch

Review of attachment 8997430 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/console/Console.cpp
@@ +1082,5 @@
>                   uint64_t aOuterWindowID, uint64_t aInnerWindowID)
>    : mWindow(aWindow)
>    , mOuterID(aOuterWindowID)
>    , mInnerID(aInnerWindowID)
> +  , mDumpToStdout(DOMPrefs::DumpEnabled())

FWIW this isn't the same as just using `browser.dom.window.dump.enabled` which is only enabled for local builds (not in automation), this will also enable for all debug builds [1]. I'm worried that we'll run into a fair amount of testing log spam, perhaps we could make this opt-in with a different pref? I provided some notes in the dev-platform thread [2].

[1] https://searchfox.org/mozilla-central/rev/f0c15db995198a1013e1c5f5b5bea54ef83f1049/dom/base/DOMPrefs.cpp#69-77
[2] https://groups.google.com/d/msg/firefox-dev/gAU6Zt0ijvg/7JEeaWmsDQAJ

Comment 5

[Brian Grinstead [:bgrins]]

(In reply to Eric Rahm [:erahm] from comment #4)
> FWIW this isn't the same as just using `browser.dom.window.dump.enabled`
> which is only enabled for local builds (not in automation), this will also
> enable for all debug builds [1]. I'm worried that we'll run into a fair
> amount of testing log spam, perhaps we could make this opt-in with a
> different pref?

I agree about having this off by default, especially in automation where this would certainly generate a lot of additional text in logs (especially for mochitests).

I'm pretty sure we do want to continue using `DOMPrefs::DumpEnabled()` behavior for system callers though, so that those logs do show up in automation logs (i.e. if you do `console.log` in a mochitest you will continue to see that in treeherder logs).

Based on the discussion in that thread, I'm leaning towards either:

1) Keep the current behavior for chrome callers and then add a second pref (false by default everywhere) to allow content logs to go out to stdout.
2) Stop overloading `browser.dom.window.dump.enabled`, and instead add two new prefs like `devtools.console.stdout.chrome` and `devtools.console.stdout.content`. The chrome variation would be true by default in local builds and automation, I guess, and the content variation would be false by default everywhere.

Comment 6

[Brian Grinstead [:bgrins]]

Comment on attachment 8997430 [details] [diff] [review]
console.patch

See Comment 5

Comment 7

[Andrea Marchesini [:baku]]

Attachment: console.patch

Comment 8

[Kartikaya Gupta (email:[e-mail])]

Any update here? I would like to see this land as it is useful to me...

Comment 9

[Brian Grinstead [:bgrins]]

Comment on attachment 9008004 [details] [diff] [review]
console.patch

Review of attachment 9008004 [details] [diff] [review]:
-----------------------------------------------------------------

Sorry about the huge delay here - I'll take a look at the next version ASAP.

::: modules/libpref/init/StaticPrefList.h
@@ +1532,5 @@
>     devtools_enabled,
>    RelaxedAtomicBool, false
>  )
>  
> +#ifdef MOZILLA_OFFICIAL

A couple notes:

1) There's a footgun here that we had to fix for the dump pref in artifact builds: https://searchfox.org/mozilla-central/rev/007b66c1f5f7a1b9a900a2038652a16a020f010c/modules/libpref/init/all.js#1090-1098.
2) In order to make console logs from parent show up everywhere in development, I think we'd also want to modify this new pref everywhere that we modify the dump pref (in tests, test harnesses, etc): https://searchfox.org/mozilla-central/search?q=browser.dom.window.dump.enabled&path=.

Given those, I think it'd be simpler to do option (1) in Comment 5 and only add the `devtools.console.stdout.content` pref. Although if you wanted to handle those 2 points above that'd be OK with me to.

Comment 10

[Andrea Marchesini [:baku]]

Attachment: console.patch

Comment 11

[Brian Grinstead [:bgrins]]

Comment on attachment 9024954 [details] [diff] [review]
console.patch

Review of attachment 9024954 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/console/Console.cpp
@@ +1092,5 @@
>    , mCreationTimeStamp(TimeStamp::Now())
>  {
>    // Let's enable the dumping to stdout by default for chrome.
>    if (nsContentUtils::ThreadsafeIsSystemCaller(aCx)) {
> +    mDumpToStdout = StaticPrefs::devtools_console_stdout_chrome();

Matt, for code like Web Payments do you rely on console.log() dumping to stdout? Because I suspect with this change it won't anymore unless if you set the 'content' pref (which would cause all web content logs to also get printed).

Perhaps there's a condition that we could use more lenient than ThreadsafeIsSystemCaller to match any script bundled inside Firefox (incl Web Payments code which runs inside a content privileged <browser> over resource:// URI:  https://searchfox.org/mozilla-central/rev/d850d799a0009f851b5535580e0a8b4bb2c591d7/browser/components/payments/docs/index.rst#33.

Comment 12

[Matthew N. [:MattN]]

Comment on attachment 9024954 [details] [diff] [review]
console.patch

Review of attachment 9024954 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/console/Console.cpp
@@ +1092,5 @@
>    , mCreationTimeStamp(TimeStamp::Now())
>  {
>    // Let's enable the dumping to stdout by default for chrome.
>    if (nsContentUtils::ThreadsafeIsSystemCaller(aCx)) {
> +    mDumpToStdout = StaticPrefs::devtools_console_stdout_chrome();

Yeah, outputting from Web Payments to stdout is really useful for debugging tests but IIUC the logging from the unprivileged portion already wouldn't work now (since ThreadsafeIsSystemCaller would return false), right?

Comment 13

[Brian Grinstead [:bgrins]]

Comment on attachment 9024954 [details] [diff] [review]
console.patch

Review of attachment 9024954 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/console/Console.cpp
@@ +1092,5 @@
>    , mCreationTimeStamp(TimeStamp::Now())
>  {
>    // Let's enable the dumping to stdout by default for chrome.
>    if (nsContentUtils::ThreadsafeIsSystemCaller(aCx)) {
> +    mDumpToStdout = StaticPrefs::devtools_console_stdout_chrome();

Oh, right. Maybe we can look into this in a follow up then. Andrea, do you know if there's a condition we can use that would allow code like Web Payments to get outputted as stdout?

Comment 14

[Brian Grinstead [:bgrins]]

Comment on attachment 9024954 [details] [diff] [review]
console.patch

Review of attachment 9024954 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/console/Console.cpp
@@ -1092,5 @@
>    , mCreationTimeStamp(TimeStamp::Now())
>  {
>    // Let's enable the dumping to stdout by default for chrome.
>    if (nsContentUtils::ThreadsafeIsSystemCaller(aCx)) {
> -    mDumpToStdout = DOMPrefs::DumpEnabled();

It looks like DOMPrefs::DumpEnabled ignores the pref and is always true in debug builds. Given that we are setting true by default in local builds for this new pref I think it's OK to switch to just the pref lookup and drop that special case.

::: modules/libpref/init/StaticPrefList.h
@@ +1755,5 @@
>    RelaxedAtomicBool, false
>  )
>  
> +#ifdef MOZILLA_OFFICIAL
> +# define PREF_VALUE false

Based on this comment: https://bugzilla.mozilla.org/show_bug.cgi?id=1490412#c14. I think it might be possible to drop the default values for these two (and the dump one) in this file, since all.js properly defines them based on MOZILLA_OFFICIAL. Would remove a bit of duplication - up to you.

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/210675b3647c
Allow Console API to log messages on stdout, r=bgrins

Comment 16

[Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)]

Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/14086 for changes under testing/web-platform/tests

Comment 17

[Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)]

Upstream web-platform-tests status checks passed, PR will merge once commit reaches central.

Comment 18

[Bogdan Tara[:bogdan_tara | bogdant]]

https://hg.mozilla.org/mozilla-central/rev/210675b3647c

Comment 19

[Andreas Tolfsen ❲:ato❳]

Please note that this commit makes changes to
testing/geckodriver/src/prefs.js for which it is a requirement to
get Testing :: geckodriver peer review.  I post-reviewed the changes
and they appear to be fine, although if this is a flag picked up
at runtime, you could get away with only having changed
testing/marionette/components/marionette.js.

Comment 20

[Andreas Tolfsen ❲:ato❳]

This patch appears to hook console.log up to
browser.dom.window.dump.enabled.  In automation we have relied on
the latter preference to surface calls to dump() which isn’t
extensively used by websites.  This has allowed us to use dump()
in both web content and chrome code, in particular through logging
libraries such as Log.jsm, to output automation logging _without_
surfacing web content document logs.

If I read the documentation added to
devtools/docs/getting-started/development-profiles.md correctly,
the new devtools.console.stdout.chrome and devtools.console.stdout.content
prefs control the relationship between console.log and dump() that
I described above.

The patch sets devtools.console.stdout.chrome to true for geckodriver
and Marionette.  From where is this used?  By console.log invocations
in the Browser Toolbox only?

If I then have understood things correctly, by not enabling
devtools.console.stdout.content in automation we avoid console.log
from propagating to stdout for regular web content.  And by keeping
browser.dom.window.dump.enabled set to true, dump() will continue
to work in web content (which is what Log.jsm in frame scripts rely
on).

Comment 21

[Andrea Marchesini [:baku]]

> If I read the documentation added to
> devtools/docs/getting-started/development-profiles.md correctly,
> the new devtools.console.stdout.chrome and devtools.console.stdout.content
> prefs control the relationship between console.log and dump() that
> I described above.

There is not a relationship between dump() and console(). dump, console in chrome and console in content have 3 separate prefs. We probably need to improve the documentation:

. browser.dom.window.dump.enabled enables dump() in windows, workers and worklets.
. devtools.console.stdout.chrome enables the stdout logging in console API when used in chrome contexts
. devtools.console.stdout.content enables the stdout logging in console API when used in content contexts

> If I then have understood things correctly, by not enabling
> devtools.console.stdout.content in automation we avoid console.log
> from propagating to stdout for regular web content.  And by keeping
> browser.dom.window.dump.enabled set to true, dump() will continue
> to work in web content (which is what Log.jsm in frame scripts rely
> on).

Right.

What do you think the default values for devtools.console.stdout.chrome and devtools.console.stdout.content prefs should be for marionette?

Comment 22

[Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)]

Upstream PR merged

Comment 23

[Andreas Tolfsen ❲:ato❳]

(In reply to Andrea Marchesini [:baku] from comment #21)

> What do you think the default values for
> devtools.console.stdout.chrome and devtools.console.stdout.content
> prefs should be for marionette?

True for .chrome and false for .content, as we want to avoid e.g.
console.log() from appearing in stdout when using geckodriver for
the time being.

This appears to be how it is defined now.