search

mozilla / geckodriver

WebDriver for Firefox
https://firefox-source-docs.mozilla.org/testing/geckodriver/
Mozilla Public License 2.0
7.19k stars 1.52k forks source link

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

Open barancev opened 7 years ago

barancev commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

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

whimboo commented 7 years ago

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

barancev commented 7 years ago

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

whimboo commented 7 years ago

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.

whimboo commented 7 years ago

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

andreastt commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

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

whimboo commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

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

titusfortner commented 1 year ago

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

whimboo commented 1 year ago

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.