Open Bug 1399441 Opened 5 years ago Updated 2 months ago
Hide Firefox stdout/stderr if log level is info level or higher
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.
I guess this necessitates a change in rust_mozrunner: https://github.com/jgraham/rust_mozrunner/blob/master/src/runner.rs#L112-L113
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).
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.
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
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
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.
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.