SeleniumHQ / selenium

A browser automation framework and ecosystem.
https://selenium.dev
Apache License 2.0
30.75k stars 8.2k forks source link

Cannot set logging options for Gecko via DesiredCapabilities and moz:firefoxOptions #3943

Closed schmidtkp closed 7 years ago

schmidtkp commented 7 years ago

Meta -

OS: OSX Selenium Version: 3.4.0 (Java bindings) Browser: Firefox Browser Version: 53.0 GeckoDriver Version: 0.16.1

Expected Behavior -

Should be able to set logging for Gecko via DesiredCapabilities using key "moz:firefoxOptions" and a JsonObject value of "{log: {level: trace}}"

Actual Behavior -

org.openqa.selenium.WebDriverException: Firefox option was set, but is not a FirefoxOption: {"log":{"level":"trace"}}

Steps to reproduce -

JsonObject asJsonObject = new JsonParser().parse("{log: {level: trace}}").getAsJsonObject(); DesiredCapabilities desiredCapabilities = DesiredCapabilities.firefox(); desiredCapabilities.setCapability("moz:firefoxOptions", asJsonObject); FirefoxDriver firefoxDriver = new FirefoxDriver(desiredCapabilities);

-- or --

RemoteWebDriver remoteWebDriver = new RemoteWebDriver(hubUrl, desiredCapabilities);

kvalev commented 7 years ago

I think the correct usage is:

FirefoxOptions options = new FirefoxOptions();
options.setLogLevel(Level.ALL);
capabilities.setCapability("moz:firefoxOptions", options);

However this did not work for me, geckodriver was still using the loglevel info. I had to extend the existing GeckoDriverService.Builder in order to pass the --log argument:

        GeckoDriverService.Builder builder = new Builder2().usingPort(0);
        Optional<FirefoxBinary> binary = options.getBinaryOrNull();
        if (binary.isPresent()) {
            builder.usingFirefoxBinary(binary.get());
        }

        GeckoDriverService gecko = builder
                .withLogFile(new File("geckodriver.log"))
                .build();

        return new FirefoxDriver(gecko, capabilities);
private static final class Builder2 extends GeckoDriverService.Builder {
        @Override
        protected ImmutableList<String> createArgs() {
            ImmutableList.Builder<String> argsBuilder = ImmutableList.builder();
            argsBuilder.addAll(super.createArgs());
            argsBuilder.add("--log");
            argsBuilder.add("trace");

            return argsBuilder.build();
        }
    }
schmidtkp commented 7 years ago

@kvalev I don't believe using FirefoxOptions.setLogLevel() will set the GeckoDriver logs based on what I've read from @andreastt posts.

kvalev commented 7 years ago

Well the suggested way (described in #3002 and #3550) seems to be manually starting geckodriver with the desired configuration, but I was looking for a more automated solution and came up with the workaround above. The only downside is that the constructor is deprecated.

lmtierney commented 7 years ago

I will re-iterate and expand on what I wrote in #3550. Selenium is sending the correct capabilities to geckodriver and the logging is set correctly. You will always see the INFO about starting geckodriver unless you add an argument to the service itself since geckodriver needs to be running in order to set the logging level with capabilities. The verbose logging you are still seeing (e.g. the debug messages) is coming from Firefox itself. Selenium has no control over these. If you have a trace I could look at that suggests otherwise @kvalev I'd be glad to look at it.

kvalev commented 7 years ago

I am not sure whether the Java binding implementation behaves like it is supposed to, but I guess it would be nice, if geckodriver is started (via GeckoDriverService) with the same log level, as the one configured in the FirefoxOptions.

schmidtkp commented 7 years ago

@kvalev @lmtierney All I'm wanting to do is set the GeckoDriver log level to 'trace' to help provide debug info to @andreastt, per what is indicated in https://github.com/mozilla/geckodriver/blob/master/README.md can be done via WebDriver capabilities (see Capabilities examples section)

lmtierney commented 7 years ago

@schmidtkp I was moreso just commenting to @kvalev. All you need to do is this:

    FirefoxOptions opts = new FirefoxOptions().setLogLevel(Level.ALL);
    WebDriver driver = new FirefoxDriver(opts);

Level.ALL translates to trace for geckodriver. I have tried and confirmed this will work with 3.4 java bindings.

schmidtkp commented 7 years ago

@lmtierney Your example is not setting the FirefoxOptions in the DesiredCapabilities. It is passing them to the FirefoxDriver(FirefoxOptions) constructor instead of the FirefoxDriver(DesiredCapabilities) constructor or the RemoteWebDriver(URL, DesiredCapabilities) constructor. We should be able to do:

FirefoxOptions options = new FirefoxOptions();
options.setLogLevel(Level.ALL);
capabilities.setCapability("moz:firefoxOptions", options);

but as @kvalev and I noted, this does not work.

lmtierney commented 7 years ago

In my example it gets converted to DesiredCapabilities. https://github.com/SeleniumHQ/selenium/blob/master/java/client/src/org/openqa/selenium/firefox/FirefoxDriver.java#L108

If you want to do it with RemoteWebDriver that's different, but since you said or I didn't realize you needed both. Did you try my example? Does it not work for you? It works for me

You can just as easily do this for remote

RemoteWebDriver remoteWebDriver = new RemoteWebDriver(hubUrl, opts.toCapabilities());
lmtierney commented 7 years ago

If you're looking to do something more like this

FirefoxOptions options = new FirefoxOptions();
options.setLogLevel(Level.ALL);
capabilities.setCapability("moz:firefoxOptions", options);

Try this instead

FirefoxOptions options = new FirefoxOptions();
options.setLogLevel(Level.ALL);
capabilities = options.addTo(capabilities);

Let the code set the moz:firefoxOptions key, that is the intended way

lmtierney commented 7 years ago

EDIT: The comment this was in response to now appears to be deleted. I am leaving this up here regardless in case it helps someone

Ok so I'm going to need more information on exactly how you are using it as I can't answer blindly anymore. If you are using this with RemoteWebDriver, the trace logging may be swallowed.

I will speak to the example I provided, however:

FirefoxOptions will eventually get toJson called on it before sending it over the wire, here is the output: {"prefs":{},"log":{"level":"trace"},"args":[]}. It gets converted to trace here: https://github.com/SeleniumHQ/selenium/blob/master/java/client/src/org/openqa/selenium/firefox/FirefoxOptions.java#L587

Given this example, again:

    FirefoxOptions opts = new FirefoxOptions().setLogLevel(Level.ALL);
    System.out.println(opts.toCapabilities().asMap());
    System.out.println(opts.toJson());
    WebDriver driver = new FirefoxDriver(opts);
    driver.get("http://www.google.com")
    driver.quit();

This is the output:

{moz:firefoxOptions={binary=Optional.empty, args=[], legacy=false, logLevel=ALL, prefs={}, profile=null}}
{"prefs":{},"log":{"level":"trace"},"args":[]}
1493758611592   geckodriver INFO    Listening on 127.0.0.1:48683
1493758611942   geckodriver::marionette INFO    Starting browser /Applications/Firefox.app/Contents/MacOS/firefox-bin with args ["-marionette"]
1493758611945   geckodriver::marionette TRACE     connection attempt 0/600
1493758612049   geckodriver::marionette TRACE     connection attempt 1/600
1493758612153   geckodriver::marionette TRACE     connection attempt 2/600
1493758612257   geckodriver::marionette TRACE     connection attempt 3/600
1493758612361   geckodriver::marionette TRACE     connection attempt 4/600
1493758612465   geckodriver::marionette TRACE     connection attempt 5/600
1493758612570   geckodriver::marionette TRACE     connection attempt 6/600
1493758612674   geckodriver::marionette TRACE     connection attempt 7/600
1493758612780   geckodriver::marionette TRACE     connection attempt 8/600
1493758612805   Marionette  DEBUG   Marionette enabled via command-line flag
1493758612884   geckodriver::marionette TRACE     connection attempt 9/600
1493758612988   geckodriver::marionette TRACE     connection attempt 10/600
1493758613093   geckodriver::marionette TRACE     connection attempt 11/600
1493758613194   geckodriver::marionette TRACE     connection attempt 12/600
1493758613300   geckodriver::marionette TRACE     connection attempt 13/600
1493758613401   geckodriver::marionette TRACE     connection attempt 14/600
1493758613505   geckodriver::marionette TRACE     connection attempt 15/600
1493758613609   geckodriver::marionette TRACE     connection attempt 16/600
1493758613713   geckodriver::marionette TRACE     connection attempt 17/600
1493758613818   geckodriver::marionette TRACE     connection attempt 18/600
1493758613832   Marionette  INFO    Listening on port 52298
1493758613923   geckodriver::marionette DEBUG   Connected to Marionette on localhost:52298
1493758613925   Marionette  DEBUG   Accepted connection conn0 from 127.0.0.1:52342
1493758613925   geckodriver::marionette TRACE   ← {"applicationType":"gecko","marionetteProtocol":3}
1493758613925   geckodriver::marionette TRACE   → 62:[0,1,"newSession",{"capabilities":{"desiredCapabilities":{}}}]
1493758613926   Marionette  TRACE   conn0 -> [0,1,"newSession",{"capabilities":{"desiredCapabilities":{}}}]
1493758613929   Marionette  CONFIG  Matched capabilities: {"browserName":"firefox","browserVersion":"53.0","platformName":"darwin","platformVersion":"16.5.0","pageLoadStrategy":"normal","acceptInsecureCerts":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"rotatable":false,"specificationLevel":0,"moz:processID":29818,"moz:profile":"/var/folders/lp/kxd1t1m9113fpq4fv8r2gyrw0000gq/T/rust_mozprofile.iThbHSsvUde0","moz:accessibilityChecks":false}
1493758614177   Marionette  TRACE   conn0 <- [1,1,null,{"sessionId":"6cfa8da3-58e3-7f44-b2bb-ccac4550bda2","capabilities":{"browserName":"firefox","browserVersion":"53.0","platformName":"darwin","platformVersion":"16.5.0","pageLoadStrategy":"normal","acceptInsecureCerts":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"rotatable":false,"specificationLevel":0,"moz:processID":29818,"moz:profile":"/var/folders/lp/kxd1t1m9113fpq4fv8r2gyrw0000gq/T/rust_mozprofile.iThbHSsvUde0","moz:accessibilityChecks":false}}]
1493758614179   geckodriver::marionette TRACE   ← [1,1,null,{"sessionId":"6cfa8da3-58e3-7f44-b2bb-ccac4550bda2","capabilities":{"browserName":"firefox","browserVersion":"53.0","platformName":"darwin","platformVersion":"16.5.0","pageLoadStrategy":"normal","acceptInsecureCerts":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"rotatable":false,"specificationLevel":0,"moz:processID":29818,"moz:profile":"/var/folders/lp/kxd1t1m9113fpq4fv8r2gyrw0000gq/T/rust_mozprofile.iThbHSsvUde0","moz:accessibilityChecks":false}}]
1493758614179   webdriver::server   DEBUG   ← 200 OK {"value": {"sessionId":"6cfa8da3-58e3-7f44-b2bb-ccac4550bda2","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"53.0","moz:accessibilityChecks":false,"moz:processID":29818,"moz:profile":"/var/folders/lp/kxd1t1m9113fpq4fv8r2gyrw0000gq/T/rust_mozprofile.iThbHSsvUde0","pageLoadStrategy":"normal","platformName":"darwin","platformVersion":"16.5.0","rotatable":false,"specificationLevel":0,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000}}}}
May 02, 2017 3:56:54 PM org.openqa.selenium.remote.ProtocolHandshake createSession
INFO: Detected dialect: W3C
2017-05-02 15:56:54.234 plugin-container[29819:29023684] *** CFMessagePort: bootstrap_register(): failed 1100 (0x44c) 'Permission denied', port = 0x9e3b, name = 'com.apple.tsm.portname'
See /usr/include/servers/bootstrap_defs.h for the error codes.
2017-05-02 15:56:54.234 plugin-container[29819:29023684] *** CFMessagePort: bootstrap_register(): failed 1100 (0x44c) 'Permission denied', port = 0xa203, name = 'com.apple.CFPasteboardClient'
See /usr/include/servers/bootstrap_defs.h for the error codes.
1493758614237   webdriver::server   DEBUG   → POST /session/6cfa8da3-58e3-7f44-b2bb-ccac4550bda2/url {"url":"http://www.google.com"}
1493758614237   geckodriver::marionette TRACE   → 43:[0,2,"get",{"url":"http://www.google.com"}]
1493758614238   Marionette  TRACE   conn0 -> [0,2,"get",{"url":"http://www.google.com"}]
1493758615133   Marionette  TRACE   conn0 <- [1,2,null,{}]
1493758615135   geckodriver::marionette TRACE   ← [1,2,null,{}]
1493758615135   webdriver::server   DEBUG   ← 200 OK {"value": {}}
schmidtkp commented 7 years ago

@lmtierney First, apologies. I was chasing my tail thinking the GeckoDriver log level was never being handled in the DesiredCapabilities due to an upstream failure from setting the browser version in the DesiredCapabilities:

org.openqa.selenium.WebDriverException: Unrecognized channel: 53.0

This error is why I wanted to get the log level set in the first place. But this error surfaces before anything gets logged by GeckoDriver, hence my incorrect assumption that the log level was not working. Sorry about that. If I remove setting the browser version, the error is not triggered and I do get GeckoDriver TRACE logs if-and-only-if I use FirefoxDriver.

However, I do think there might be some truth in what you said:

If you are using this with RemoteWebDriver, the trace logging may be swallowed.

When I use RemoteWebDriver I at least see geckodriver::marionette INFO but never any geckodriver::marionette TRACE.

In addition, I overlooked my logback appender logger levels. But even after setting these to ALL I still do not see TRACE logs when using RemoteWebDriver.

lmtierney commented 7 years ago

Alright now I've got something to work with. Can you share the code you're using to create the webdriver?

lmtierney commented 7 years ago

Ah ok it seems you already created an issue for that, and I see some chatter in IRC about it, so I defer to #3941

andreastt commented 7 years ago

To be crystal clear about what geckodriver’s expectations are without jumping into the Java code, geckodriver expects the following input to enable trace-level logs:

{"moz:firefoxOptions": {"log": {"level": "trace"}}}

The moz:firefoxOptions field should be a member of the appropriate requested capabilities object, meaning that for W3C WebDriver conforming new session negotiations, it should be member of the JSON Object assigned to alwaysMatch, or one of the JSON Objects entries to the firstMatch array.

Example of alwaysMatch:

{"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"log": {"level": "trace"}}}}}

Example of firstMatch:

{"capabilities": {"firstMatch": [{"moz:firefoxOptions": {"log": {"level": "trace"}}}]}}

Because Selenium appear to be using the non-conforming new session negotiation with desired- and required capabilities, we didn’t remove legacy support for this in geckodriver yet. This means geckodriver for the time being also supports the following input:

{"desiredCapabilities": {"moz:firefoxOptions": {"log": {"level": "trace"}}}}

Now, what separates W3C WebDriver new session negotiation from legacy Selenium WebDriver negotiation, and how can you tell?

When geckodriver receives a JSON Object to POST /session with a top-level capabilities key, such as {"capabilities": …}, it goes into WebDriver-conforming negotiation mode to look for alwaysMatch/firstMatch. If there is no top-level capabilities field, it looks for desiredCapabilities/requiredCapabilities.

lmtierney commented 7 years ago

@andreastt thank you for clarifying. Simon is currently working on conforming the w3c new session capabilities (for server/grid as well)

andreastt commented 7 years ago

@lmtierney You can find my email easily if you have any questions. I’m also known as ato in the #webdriver IRC channel on irc.w3.org during London hours. Happy to help out or offer moral support for enduring the transition.

allengay commented 7 years ago

@lmtierney I believe I tried your solution: FirefoxDriverManager.getInstance().setup(); this.ffProfile = profile.getProfile("AllenFFProfile"); this.ffProfile.setPreference("network.automatic-ntlm-auth.trusted-uris", this.URL); DesiredCapabilities capabilities = DesiredCapabilities.firefox(); FirefoxOptions options = new FirefoxOptions(); options.setLogLevel(Level.WARNING); capabilities = options.addTo(capabilities); capabilities.setCapability(FirefoxDriver.PROFILE, ffProfile); this.driver = new FirefoxDriver(capabilities); but I am still getting level info with all the "debug" logging

lmtierney commented 7 years ago

Show your stack trace

Moustakas42 commented 7 years ago

Also can't limit the FirefoxDriver log. Have tried:

FirefoxOptions options = new FirefoxOptions();
options.setLogLevel(Level.OFF);
options.addArguments("--log fatal");

And even adding these to my profile file:

user_pref("marionette.log.level", "FATAL");
user_pref("marionette.logging", "FATAL");

Console output still looks like:

1498739575317   geckodriver INFO    Listening on 127.0.0.1:48480
1498739576168   addons.manager  DEBUG   Application has been upgraded
1498739576169   addons.manager  ERROR   startup failed: [Exception... "Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIFile.create]"  nsresult: "0x80070057 (NS_ERROR_ILLEGAL_VALUE)"  location: "JS frame :: resource://gre/modules/FileUtils.jsm :: FileUtils_getDir :: line 70"  data: no] Stack trace: FileUtils_getDir()@resource://gre/modules/FileUtils.jsm:70 < FileUtils_getFile()@resource://gre/modules/FileUtils.jsm:42 < validateBlocklist()@resource://gre/modules/AddonManager.jsm:674 < startup()@resource://gre/modules/AddonManager.jsm:837 < startup()@resource://gre/modules/AddonManager.jsm:3145 < observe()@resource://gre/components/addonManager.js:65
1498739576170   addons.manager  DEBUG   Completed startup sequence
JavaScript error: resource://gre/modules/AddonManager.jsm, line 1657: NS_ERROR_NOT_INITIALIZED: AddonManager is not initialized
[GPU 9224] WARNING: pipe error: 109: file c:/builds/moz2_slave/m-rel-w32-00000000000000000000/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
*** Blocklist::_preloadBlocklistFile: blocklist is disabled
JavaScript error: resource://gre/modules/AddonManager.jsm, line 2572: NS_ERROR_NOT_INITIALIZED: AddonManager is not initialized
1498739579909   Marionette  DEBUG   loaded listener.js
Jun 29, 2017 2:32:59 PM org.openqa.selenium.remote.ProtocolHandshake createSession
INFO: Detected dialect: W3C

I'm on FF 54, Selenium 3.4, Geckodriver 0.17, Java bindings.

andreastt commented 7 years ago

@Moustakas42 To be clear, you can only limit output from the Marionette logger in Firefox and geckodriver, and not addons.manager and others.

That options.setLogLevel(Level.OFF) does not work I suspect is a bug with the Selenium Java client, since geckodriver --log warn works fine.

Moustakas42 commented 7 years ago

@andreastt so is there currently any way to limit the Marionette logger? None of the options I listed produced any effects.

andreastt commented 7 years ago

@Moustakas42 In geckodriver you can use --log fatal to only print fatal level and above. I don’t think there is an option to disable all logging, but using this will effectively achieve that effect.

Moustakas42 commented 7 years ago

@andreastt how can I pass this in Java? options.addArguments("--log fatal"); didn't yield any effect.

andreastt commented 7 years ago

@Moustakas42 options.setLogLevel(Level.FATAL) I imagine. The arguments will be propagated to Firefox, not geckodriver.

Moustakas42 commented 7 years ago

@andreastt is that java.util.logging.Level? It goes up to SEVERE (no FATAL), and I still get:

1499757968209   Marionette  DEBUG   Received DOM event "beforeunload" for "about:blank"
1499757969295   Marionette  DEBUG   Received DOM event "beforeunload" for "about:blank"
1499757969298   Marionette  DEBUG   Received DOM event "pagehide" for "about:blank"
1499757969298   Marionette  DEBUG   Received DOM event "unload" for "about:blank"
Mark-Reiser commented 7 years ago

@Moustakas42 and @andreastt

I experience the same problems and tried several ways to deactivate any debugging but without success.

Has anyone an idea to turn off all the "Marionette DEBUG Received DOM event" messages?

I use FF 55.0.3, Geckodriver 0.18.0, Selenium 3.5.3, JUnit 3.12

andreastt commented 7 years ago

@Moustakas42 @Mark-Reiser Those entries are at the moment unconditionally printed by Marionette irregardless of the log level. This is a known issue tracked by https://bugzilla.mozilla.org/show_bug.cgi?id=1384956.

cc @whimboo