geckodriver
geckodriver copied to clipboard
mozilla
Some log messages leak even if the log level is "fatal"
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
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.
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?
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.
Put into other words: This is output you’d see from Firefox normally, even when not run through geckodriver.
I just wonder if the binary used to produce this trace log was a debug build?
So what we do in GeckoDriver is to set browser.dom.window.dump.enabled to true:
https://github.com/mozilla/geckodriver/blob/2e0054b90ecf1acbe8b442af54441e3cc746933f/src/prefs.rs#L23
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.
@andreastt I would recommend that we re-open this issue. Sadly I cannot do it myself.
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
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?
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.
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.
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.
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?
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/"
The debug-level output you see from the Marionette component there is due to https://bugzilla.mozilla.org/show_bug.cgi?id=1384956.
Did https://bugzilla.mozilla.org/show_bug.cgi?id=1384956 not address the issue?
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.