1399441 - Hide Firefox stdout/stderr if log level is info level or higher

Status: NEW

(Testing :: geckodriver, enhancement, P3)

Description

[Andreas Tolfsen ❲:ato❳]

Many users of geckodriver are confused by the stdout from Firefox,
especially because we cannot control all types of output there.  To
improve the user experience we could redirect Firefox stdout/stderr
to /dev/null unless log output is being explicitly requested.

We could apply the same solution we have for "./mach marionette
test", where "--gecko-log -" redirects the Firefox stdout to the
current stdout (or a file handle), but I’m wary of applying the
same approach to geckodriver because it means one more configuration
option for users to worry about when we ask for trace-level log.

Instead, my proposal is redirect the Firefox stdout to /dev/null by
default, unless the log level is lower than info.  So for example

	% geckodriver --log info

would not show the Firefox output, but

	% geckodriver --log warn

would.

Comment 1

[Andreas Tolfsen ❲:ato❳]

I guess this necessitates a change in rust_mozrunner:

	https://github.com/jgraham/rust_mozrunner/blob/master/src/runner.rs#L112-L113

Comment 2

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

We cannot simply ignore the output from Firefox because our Marionette debug/tracing log output is also included. And as I can remember you were against such a filtering when I talked about it in a chitchat a couple weeks ago.

So basically what we have to solve first is bug 1384956, so that we no longer log debug lines if INFO level is specified. Then we can see what would still be needed for geckodriver.

Comment 3

[Andreas Tolfsen ❲:ato❳]

(In reply to Henrik Skupin (:whimboo) from comment #2)

> We cannot simply ignore the output from Firefox because our Marionette
> debug/tracing log output is also included. And as I can remember you
> were against such a filtering when I talked about it in a chitchat a
> couple weeks ago.
> 
> So basically what we have to solve first is bug 1384956, so that we
> no longer log debug lines if INFO level is specified. Then we can see
> what would still be needed for geckodriver.

That is a separate bug which we need to fix in any case, but I
don’t think it is a prerequisite for this?  The status quo is that
debug-level log entries from testing/marionette/listener.js are printed
unconditionally, regardless of your chosen log level, as if they were
regular printf/dump statements.  The proposal here is to not show output
from Firefox if the _chosen log level_ is info or higher.

Implicitly, this means the messages you are concerned about will be
shown for as long as a lower log level than info is shown (e.g. passing
-v or -vv flags).

Comment 4

[Andreas Tolfsen ❲:ato❳]

I have started the long march to remove unnecessarily chatty
log output by patching https://bugzil.la/1384956 with a
workaround to get the log level from the main process.
This fixes the always-on-debug-statements problem with
testing/marionette/listener.js.

Comment 5

[Andreas Tolfsen ❲:ato❳]

Submitted https://github.com/jgraham/rust_mozrunner/pull/16 to
mozrunner as a prerequisite for this.

Comment 6

[Andreas Tolfsen ❲:ato❳]

Attachment: Bug 1399441 - Hide Firefox stdout/stderr if log level is info level or higher

This patch will quench stdout/stderr from Firefox by default, which
is believed to cause unneeded confusion amongst geckodriver users
leading them to file false bugs.

If the effective log level is config or lower (config/debug/trace)
the output will be inherited as it is is currently.

Review commit: https://reviewboard.mozilla.org/r/206698/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/206698/

Comment 7

[Andreas Tolfsen ❲:ato❳]

This now depends on bug 1436830 because that contains a refactor of logging.rs.

Comment 9

[Andreas Tolfsen ❲:ato❳]

This requires a bit more work than I first imagined, because we
need to preserve the Marionette log from Firefox.  Perhaps a better
strategy would be to file upstream bugs on Gecko and Firefox.

I also ran into problems with std::process::Command not silencing
the stdout of Firefox’ subprocess.  I didn’t look into this too
much.

Comment 10

[Andreas Tolfsen ❲:ato❳]

OK, so I think what we should do here is filter the Firefox stdout
ourselves, much like you would imagine doing with a combination of
awk(1) to get the right column and with grep(1) to look for the
correct lines.

Comment 11

[Andreas Tolfsen ❲:ato❳]

Since log messages can span multiple lines, this turned out to be
a bit more complicated than I had initially anticipated.  To cater
for multi-line messages the output from Marionette needs to be
emitted in a structured format.  I wrote a patch that used Log.jsm’s
StructuredFormatter, but this was removed in
https://bugzilla.mozilla.org/show_bug.cgi?id=1480327.

In an ideal world we wouldn’t write the Marionette log messages to
stdout at all, but instead have an actual Marionette service that
the client could enable when it is interested in logs.  I suppose
we can look at this following
https://bugzilla.mozilla.org/show_bug.cgi?id=1330309.

Comment 12

[Andreas Tolfsen ❲:ato❳]

Attachment: Make FirefoxProcess::process public.

The std::process::Child owned by FirefoxProcess needs to be public in order to gain access to its stdout.

Comment 13

[Andreas Tolfsen ❲:ato❳]

Attachment: Hide Firefox stdout+stderr if log level >= info.

Many users of geckodriver are confused by the stdout from Firefox,
especially because we cannot control all types of output.  This patch
changes geckodriver to only propagate log messages from the Marionette
XPCOM component at normal logging verbosity (info) and finer.

This means setting the log level to config, debug, or trace will
include all stdout, whereas all finer levels (info, warn, error,
fatal) will filter out everything that does not originate from Marionette.

The stderr will likewise only be propagated when full non-filtered
logging is enabled.  In practice, however, we don't see many messages
on this stream.

Comment 14

[Andreas Tolfsen ❲:ato❳]

Attachment: wip

Comment 15

[Andreas Tolfsen ❲:ato❳]

On further reflection, I think going in the direction I discussed
in https://bugzilla.mozilla.org/show_bug.cgi?id=1399441#c11 may be
a better long-term solution.  I’ve attached a couple of patches
which demonstrate how we can do this parsing the stdout, but I am
hesitant to implement a stop-gap solution.