Some log messages leak even if the log level is "fatal"

[barancev]

Firefox Version

55.0a1 (2017-04-06) (64-bit)
geckodriver 0.15

Platform

Windows 7

Steps to reproduce

        FirefoxOptions options = new FirefoxOptions()
                .setBinary(new FirefoxBinary(FirefoxBinary.Channel.NIGHTLY))
                .setLogLevel(Level.OFF);
        WebDriver driver = new FirefoxDriver(options);
        driver.get("http://seleniumhq.org/");

Most log messages are suppressed, but not all:

1491680124872	geckodriver	INFO	Listening on 127.0.0.1:47616
[GPU 12236] WARNING: pipe error: 109: file c:/builds/moz2_slave/m-cen-w64-ntly-000000000000000/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
[Child 12748] WARNING: pipe error: 109: file c:/builds/moz2_slave/m-cen-w64-ntly-000000000000000/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
апр 08, 2017 10:35:28 PM org.openqa.selenium.remote.ProtocolHandshake createSession
JavaScript error: http://www.seleniumhq.org/tophatpromo.js, line 1: ReferenceError: $ is not defined
JavaScript error: http://www.seleniumhq.org/tophatpromo.js, line 1: ReferenceError: $ is not defined

[andreastt]

Thanks for the bug report, but unfortunately the log verbosity option in geckodriver only controls the Log.jsm and the Rust verbosity.

The “pipe error”, “ProtocolHandshake createSession”, and “JavaScript error” output that you see in your log is outside of our control.

[barancev]

Why can't geckodriver handle "pipe error" and "JavaScript error"? They came from the browser, why can't they be wrapped (and then suppressed) by geckodriver?

[andreastt]

Because they’re not using Log.jsm, and whatever isn’t using Log.jsm is outside of our control. The log verbosity setting only controls the Marionette log component.

[andreastt]

Put into other words: This is output you’d see from Firefox normally, even when not run through geckodriver.

[whimboo]

I just wonder if the binary used to produce this trace log was a debug build?

[barancev]

Firefox Nightly and the released version of geckodriver 0.15 for windows.

[whimboo]

So what we do in GeckoDriver is to set browser.dom.window.dump.enabled to true:

geckodriver/src/prefs.rs

Line 23 in 2e0054b

("browser.dom.window.dump.enabled", Pref::new(true)),

Can you please check how it behaves when you turn it off?

This preference actually controls everything which gets dumped to the console by the browser itself. Maybe we should couple it with the log settings, and only turn it on if logging is enabled and set to at least debug level.

[whimboo]

@andreastt I would recommend that we re-open this issue. Sadly I cannot do it myself.

[andreastt]

browser.dom.window.dump.enabled only controls the visibility of dump() in JS. It does not control std::cout or printf in C++ or C.

For example, I still see this which originates from C++ code:

[Child 6346] WARNING: pipe error (29): Connection reset by peer: file /home/ato/src/gecko/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 353
[Child 6346] WARNING: pipe error (16): Connection reset by peer: file /home/ato/src/gecko/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 353
[Child 6346] WARNING: pipe error (3): Connection reset by peer: file /home/ato/src/gecko/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 353

But setting browser.dom.window.dump.enabled to false hides the likes of:

JavaScript warning: http://cdn.vgc.no/js/libs/backbone/backbone-1.0.0.min.js, line 2: Using //@ to indicate sourceMappingURL pragmas is deprecated. Use //# instead

[whimboo]

Even if it only controls the output dump() in JS code, we could reduce the clutter in the log, and only enable it if at least debug has been specified?

[andreastt]

Sure. I’ve always found them useful, but I guess it would be more structured to access them by implementing a log retrieval API in the future.

In the meantime, users who are interested in these log messages can pass browser.dom.window.dump.enabled as part of moz:firefoxOptions.

[whimboo]

In the meantime, users who are interested in these log messages can pass browser.dom.window.dump.enabled as part of moz:firefoxOptions.

I assume you meant not interested because we enable this preference by default in geckodriver.

[andreastt]

I assume you meant not interested because we enable this preference by default in geckodriver.

I mean that when browser.dom.window.dump.enabled is taken out of prefs.rs, users who are interested in it can pass it along as a preference in moz:firefoxOptions if they want to retain the current behaviour.

[whimboo]

Ok, so I will provide a PR for that then.

[whimboo]

So I tried to reproduce this behavior with the Selenium Python bindings but I actually cannot see any javascript errors in the log output. It doesn't matter which level I have defined.

@barancev, which binding are you using? Would you mind testing with my Python test script?

[barancev]

As far as I know Python test frameworks suppress stdout of spawned processes. I use Java binding.

At the moment I see less internal browser error messages than in the original post, but the log is not empty (in today Nightly):

1504799496623	geckodriver	INFO	geckodriver 0.18.0
1504799496632	geckodriver	INFO	Listening on 127.0.0.1:24070
Unable to read VR Path Registry from C:\Users\alexei\AppData\Local\openvr\openvrpaths.vrpath
[Child 9904] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
1504799500028	Marionette	DEBUG	Register listener.js for window 4294967297
1504799500091	Marionette	DEBUG	Received DOM event "beforeunload" for "about:blank"
1504799500419	Marionette	DEBUG	Received DOM event "pagehide" for "about:blank"
1504799500419	Marionette	DEBUG	Received DOM event "unload" for "about:blank"
1504799500602	Marionette	DEBUG	Received DOM event "DOMContentLoaded" for "http://www.seleniumhq.org/"
1504799501450	Marionette	DEBUG	Received DOM event "pageshow" for "http://www.seleniumhq.org/"

[andreastt]

The debug-level output you see from the Marionette component there is due to https://bugzilla.mozilla.org/show_bug.cgi?id=1384956.

[titusfortner]

Did https://bugzilla.mozilla.org/show_bug.cgi?id=1384956 not address the issue?

[whimboo]

Did https://bugzilla.mozilla.org/show_bug.cgi?id=1384956 not address the issue?

That bug was only about the wrong logging in Marionette, but this did not address the issue with the included Firefox logs.