Andreas Tolfsen ❲:ato❳ Reporter
	Description • 7 years ago

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.

	Andreas Tolfsen ❲:ato❳ Reporter
	Comment 1 • 7 years ago

I guess this necessitates a change in rust_mozrunner:

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

	Henrik Skupin [:whimboo][⌚️UTC+1]
	Comment 2 • 7 years ago

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.

	Andreas Tolfsen ❲:ato❳ Reporter
	Comment 3 • 7 years ago

(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).

	Andreas Tolfsen ❲:ato❳ Reporter
	Comment 4 • 7 years ago

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.

	Andreas Tolfsen ❲:ato❳ Reporter
	Comment 5 • 6 years ago

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

	Andreas Tolfsen ❲:ato❳ Reporter
	Comment 7 • 6 years ago

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

	Andreas Tolfsen ❲:ato❳ Reporter
	Comment 9 • 6 years ago

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.

	Andreas Tolfsen ❲:ato❳ Reporter
	Comment 10 • 6 years ago

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.

	Andreas Tolfsen ❲:ato❳ Reporter
	Comment 11 • 6 years ago

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.

	Andreas Tolfsen ❲:ato❳ Reporter
	Comment 12 • 6 years ago

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

	Andreas Tolfsen ❲:ato❳ Reporter
	Comment 13 • 6 years ago

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.

	Andreas Tolfsen ❲:ato❳ Reporter
	Comment 15 • 6 years ago

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.