Open Bug 1399441 Opened 2 years ago Updated Last year

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

Categories

(Testing :: geckodriver, enhancement, P3)

Version 3
enhancement

Tracking

(Not tracked)

People

(Reporter: ato, Unassigned)

References

(Depends on 1 open bug, )

Details

Attachments

(3 files, 1 obsolete file)

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.
Blocks: 1391605
I guess this necessitates a change in rust_mozrunner:

	https://github.com/jgraham/rust_mozrunner/blob/master/src/runner.rs#L112-L113
Priority: -- → P3
No longer blocks: 1391605
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.
Depends on: 1384956
(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).
No longer depends on: 1384956
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.
Assignee: nobody → ato
Status: NEW → ASSIGNED
Submitted https://github.com/jgraham/rust_mozrunner/pull/16 to
mozrunner as a prerequisite for this.
This now depends on bug 1436830 because that contains a refactor of logging.rs.
Depends on: 1436830
Priority: P3 → P1
Priority: P1 → P2
Duplicate of this bug: 1389049
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.
Status: ASSIGNED → NEW
Priority: P2 → P3
Assignee: ato → nobody
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.
Assignee: nobody → ato
Status: NEW → ASSIGNED
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.
The std::process::Child owned by FirefoxProcess needs to be public in order to gain access to its stdout.
Attachment #8935831 - Attachment is obsolete: true
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.
Attached patch wipSplinter Review
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.
Assignee: ato → nobody
Status: ASSIGNED → NEW
Depends on: 1330309
You need to log in before you can comment on or make changes to this bug.