Unable to disable legacy Firefox driver error logging

[Zlaman]

Meta -

OS: Windows 7
Selenium Version: Selenium Java 3.4.0
Browser: Firefox ESR 52.1.2 (32-bit) or Firefox 47.0.2 (32-bit)

Expected Behavior -

Firefox error logging is disabled by default.

Actual Behavior -

Many error log lines are displayed in console, like this:
1496760190989 addons.manager DEBUG Application has been upgraded
1496760191029 addons.manager DEBUG Loaded provider scope for resource://gre/modules/addons/XPIProvider.jsm: ["XPIProvider"]
1496760191031 addons.manager DEBUG Loaded provider scope for resource://gre/modules/LightweightThemeManager.jsm: ["LightweightThemeManager"]
1496760191034 addons.manager DEBUG Loaded provider scope for resource://gre/modules/addons/GMPProvider.jsm
1496760191036 addons.manager DEBUG Loaded provider scope for resource://gre/modules/addons/PluginProvider.jsm
1496760191037 addons.manager DEBUG Starting provider: XPIProvider
1496760191037 addons.xpi DEBUG startup
1496760191038 addons.xpi INFO SystemAddonInstallLocation directory is missing
1496760191039 addons.xpi INFO Mapping aushelper@mozilla.org to C:\Program Files (x86)\Mozilla Firefox\browser\features\aushelper@mozilla.org.xpi
1496760191039 addons.xpi INFO Mapping e10srollout@mozilla.org to C:\Program Files (x86)\Mozilla Firefox\browser\features\e10srollout@mozilla.org.xpi
1496760191039 addons.xpi INFO Mapping firefox@getpocket.com to C:\Program Files (x86)\Mozilla Firefox\browser\features\firefox@getpocket.com.xpi
1496760191039 addons.xpi INFO Mapping webcompat@mozilla.org to C:\Program Files (x86)\Mozilla Firefox\browser\features\webcompat@mozilla.org.xpi
1496760191040 addons.xpi INFO Mapping {972ce4c6-7e08-4474-a285-3208198ce6fd} to C:\Program Files (x86)\Mozilla Firefox\browser\extensions{972ce4c6-7e08-4474-a285-3208198ce6fd}.xpi
1496760191041 addons.xpi DEBUG Skipping unavailable install location app-system-share
1496760191041 addons.xpi DEBUG Skipping unavailable install location app-system-local

Steps to reproduce -

Start firefox legacy webdriver using:

        System.setProperty(FirefoxDriver.SystemProperty.DRIVER_USE_MARIONETTE, "false");
        new FirefoxDriver();

OR

        DesiredCapabilities capabilities = new FirefoxOptions().setLogLevel(Level.OFF).addTo(DesiredCapabilities.firefox());
        capabilities.setCapability("marionette", false);
        System.setProperty(FirefoxDriver.SystemProperty.DRIVER_USE_MARIONETTE, "false");
        new FirefoxDriver(capabilities);

Note: Issue appeared in Selenium Java 3.4.0. On Selenium Java 3.3.1 error logs were absent.

[jhmoore]

+1 here . . . without any changes in config, simply bumping to the latest selenium version is slowing down our CI due to all the log output.

Explicitly setting the logging level to fatal does successfully disable Selenium debug messages like this:

2017-07-24 15:19:14 DEBUG Selenium Executing Process ["/Applications/Firefox.app/Contents/MacOS/firefox", "-no-remote", "-foreground"]
2017-07-24 15:19:14 DEBUG Selenium polling for socket on ["127.0.0.1", 7055]

However it does not stop the logs coming from things like addons.manager, addons.xpi, addons.xpi-utils, addons.repository, or DeferredSave.extensions.json.

1500934979790	addons.manager	DEBUG	Application has been upgraded
1500934979805	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/XPIProvider.jsm: ["XPIProvider"]
1500934979806	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/LightweightThemeManager.jsm: ["LightweightThemeManager"]
1500934979808	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/GMPProvider.jsm
1500934979809	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/PluginProvider.jsm
1500934979809	addons.manager	DEBUG	Starting provider: XPIProvider
1500934979809	addons.xpi	DEBUG	startup
1500934979809	addons.xpi	INFO	Mapping fxdriver@googlecode.com to /var/folders/xk/cq9ph2g53g143lfr5qz897hw0000gn/T/webdriver-profile20170724-19474-p19978/extensions/fxdriver@googlecode.com
1500934979810	addons.xpi	INFO	SystemAddonInstallLocation directory is missing
1500934979810	addons.xpi	INFO	Mapping loop@mozilla.org to /Applications/Firefox.app/Contents/Resources/browser/features/loop@mozilla.org.xpi
1500934979811	addons.xpi	INFO	Mapping {972ce4c6-7e08-4474-a285-3208198ce6fd} to /Applications/Firefox.app/Contents/Resources/browser/extensions/{972ce4c6-7e08-4474-a285-3208198ce6fd}.xpi
1500934979811	addons.xpi	DEBUG	Skipping unavailable install location app-system-share
1500934979811	addons.xpi	DEBUG	checkForChanges
1500934979812	addons.xpi	DEBUG	Loaded add-on state from prefs: {}
1500934979812	addons.xpi	DEBUG	New add-on fxdriver@googlecode.com in app-profile
1500934979812	addons.xpi	DEBUG	getModTime: Recursive scan of fxdriver@googlecode.com
1500934979813	addons.xpi	DEBUG	New add-on loop@mozilla.org in app-system-defaults
1500934979813	addons.xpi	DEBUG	getModTime: Recursive scan of loop@mozilla.org
1500934979814	addons.xpi	DEBUG	New add-on {972ce4c6-7e08-4474-a285-3208198ce6fd} in app-global
1500934979814	addons.xpi	DEBUG	getModTime: Recursive scan of {972ce4c6-7e08-4474-a285-3208198ce6fd}
1500934979814	addons.xpi	DEBUG	getInstallState changed: true, state: {"app-profile":{"fxdriver@googlecode.com":{"d":"/var/folders/xk/cq9ph2g53g143lfr5qz897hw0000gn/T/webdriver-profile20170724-19474-p19978/extensions/fxdriver@googlecode.com","st":1500934979000,"mt":1500934979000}},"app-system-defaults":{"loop@mozilla.org":{"d":"/Applications/Firefox.app/Contents/Resources/browser/features/loop@mozilla.org.xpi","st":1491943230000}},"app-global":{"{972ce4c6-7e08-4474-a285-3208198ce6fd}":{"d":"/Applications/Firefox.app/Contents/Resources/browser/extensions/{972ce4c6-7e08-4474-a285-3208198ce6fd}.xpi","st":1491943230000}}}
1500934979819	addons.xpi-utils	DEBUG	Opening XPI database /var/folders/xk/cq9ph2g53g143lfr5qz897hw0000gn/T/webdriver-profile20170724-19474-p19978/extensions.json
1500934979820	addons.xpi-utils	DEBUG	New add-on fxdriver@googlecode.com installed in app-profile
*** Blocklist::_loadBlocklistFromFile: blocklist is disabled
1500934979829	DeferredSave.extensions.json	DEBUG	Save changes
1500934979830	addons.xpi-utils	DEBUG	New add-on loop@mozilla.org installed in app-system-defaults
1500934979833	DeferredSave.extensions.json	DEBUG	Starting timer
1500934979834	DeferredSave.extensions.json	DEBUG	Save changes
1500934979835	addons.xpi-utils	DEBUG	New add-on {972ce4c6-7e08-4474-a285-3208198ce6fd} installed in app-global
1500934979837	DeferredSave.extensions.json	DEBUG	Save changes
1500934979837	addons.xpi-utils	INFO	Hiding the updated system add-ons.
1500934979837	addons.manager	DEBUG	Registering startup change 'installed' for fxdriver@googlecode.com
1500934979837	addons.xpi-utils	DEBUG	Make addon app-profile:fxdriver@googlecode.com visible
1500934979837	DeferredSave.extensions.json	DEBUG	Save changes
1500934979843	addons.xpi	DEBUG	Loading bootstrap scope from /Applications/Firefox.app/Contents/Resources/browser/features/loop@mozilla.org.xpi
1500934979852	addons.xpi	DEBUG	Calling bootstrap method install on loop@mozilla.org version 1.1.14
1500934979853	addons.xpi-utils	DEBUG	Make addon app-system-defaults:loop@mozilla.org visible
1500934979853	DeferredSave.extensions.json	DEBUG	Save changes
1500934979853	addons.xpi-utils	DEBUG	Make addon app-global:{972ce4c6-7e08-4474-a285-3208198ce6fd} visible
1500934979853	DeferredSave.extensions.json	DEBUG	Save changes
1500934979854	addons.xpi	DEBUG	Updating XPIState for {"id":"fxdriver@googlecode.com","syncGUID":"qaea2cFZi_N7","location":"app-profile","version":"3.4.0","type":"extension","internalName":null,"updateURL":null,"updateKey":null,"optionsURL":null,"optionsType":null,"aboutURL":null,"icons":{},"iconURL":null,"icon64URL":null,"defaultLocale":{"name":"Firefox WebDriver","description":"WebDriver implementation for Firefox","creator":"Simon Stewart","homepageURL":null},"visible":true,"active":true,"userDisabled":false,"appDisabled":false,"descriptor":"/var/folders/xk/cq9ph2g53g143lfr5qz897hw0000gn/T/webdriver-profile20170724-19474-p19978/extensions/fxdriver@googlecode.com","installDate":1500934979000,"updateDate":1500934979000,"applyBackgroundUpdates":1,"bootstrap":false,"skinnable":false,"size":3303310,"sourceURI":null,"releaseNotesURI":null,"softDisabled":false,"foreignInstall":true,"hasBinaryComponents":false,"strictCompatibility":false,"locales":[],"targetApplications":[{"id":"{ec8030f7-c20a-464f-9b0e-13a3a9e97384}","minVersion":"3.0","maxVersion":"48.0"}],"targetPlatforms":[{"os":"Darwin","abi":null},{"os":"SunOS","abi":null},{"os":"FreeBSD","abi":null},{"os":"OpenBSD","abi":null},{"os":"WINNT","abi":null},{"os":"Linux","abi":null}],"multiprocessCompatible":false,"signedState":0,"seen":true}
1500934979854	addons.xpi	DEBUG	getModTime: Recursive scan of fxdriver@googlecode.com
1500934979855	addons.xpi	DEBUG	Updating XPIState for {"id":"loop@mozilla.org","syncGUID":"o4-C3KBXnrZl","location":"app-system-defaults","version":"1.1.14","type":"extension","internalName":null,"updateURL":null,"updateKey":null,"optionsURL":null,"optionsType":null,"aboutURL":null,"icons":{},"iconURL":null,"icon64URL":null,"defaultLocale":{"name":"Firefox Hello Beta","description":"Web sharing for Firefox","creator":"Mozilla","homepageURL":null},"visible":true,"active":true,"userDisabled":false,"appDisabled":false,"descriptor":"/Applications/Firefox.app/Contents/Resources/browser/features/loop@mozilla.org.xpi","installDate":1491943230000,"updateDate":1491943230000,"applyBackgroundUpdates":1,"bootstrap":true,"skinnable":false,"size":4109524,"sourceURI":null,"releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"hasBinaryComponents":false,"strictCompatibility":false,"locales":[],"targetApplications":[{"id":"{ec8030f7-c20a-464f-9b0e-13a3a9e97384}","minVersion":"45.0","maxVersion":"45.*"},{"id":"xpcshell@tests.mozilla.org","minVersion":"0","maxVersion":"10"}],"targetPlatforms":[],"multiprocessCompatible":false,"seen":true}
1500934979855	addons.xpi	DEBUG	getModTime: Recursive scan of loop@mozilla.org
1500934979855	addons.xpi	DEBUG	Updating XPIState for {"id":"{972ce4c6-7e08-4474-a285-3208198ce6fd}","syncGUID":"ccY26f8Xt-dh","location":"app-global","version":"45.9.0","type":"theme","internalName":"classic/1.0","updateURL":null,"updateKey":null,"optionsURL":null,"optionsType":null,"aboutURL":null,"icons":{"32":"icon.png","48":"icon.png"},"iconURL":null,"icon64URL":null,"defaultLocale":{"name":"Default","description":"The default theme.","creator":"Mozilla","homepageURL":null,"contributors":["Mozilla Contributors"]},"visible":true,"active":true,"userDisabled":false,"appDisabled":false,"descriptor":"/Applications/Firefox.app/Contents/Resources/browser/extensions/{972ce4c6-7e08-4474-a285-3208198ce6fd}.xpi","installDate":1491943230000,"updateDate":1491943230000,"applyBackgroundUpdates":1,"skinnable":true,"size":7140,"sourceURI":null,"releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"hasBinaryComponents":false,"strictCompatibility":true,"locales":[],"targetApplications":[{"id":"{ec8030f7-c20a-464f-9b0e-13a3a9e97384}","minVersion":"45.9.0","maxVersion":"45.9.0"}],"targetPlatforms":[],"seen":true}
1500934979856	addons.xpi	DEBUG	getModTime: Recursive scan of {972ce4c6-7e08-4474-a285-3208198ce6fd}
1500934979856	DeferredSave.extensions.json	DEBUG	Save changes
1500934979856	addons.xpi	DEBUG	Updating database with changes to installed add-ons
1500934979856	addons.xpi-utils	DEBUG	Updating add-on states
1500934979857	addons.xpi-utils	DEBUG	Writing add-ons list
1500934979858	addons.xpi	DEBUG	Registering manifest for /Applications/Firefox.app/Contents/Resources/browser/features/loop@mozilla.org.xpi
1500934979859	addons.xpi	DEBUG	Calling bootstrap method startup on loop@mozilla.org version 1.1.14
1500934979861	addons.manager	DEBUG	Registering shutdown blocker for XPIProvider
1500934979861	addons.manager	DEBUG	Provider finished startup: XPIProvider
1500934979861	addons.manager	DEBUG	Starting provider: LightweightThemeManager
1500934979861	addons.manager	DEBUG	Registering shutdown blocker for LightweightThemeManager
1500934979861	addons.manager	DEBUG	Provider finished startup: LightweightThemeManager
1500934979861	addons.manager	DEBUG	Starting provider: GMPProvider
1500934979866	addons.manager	DEBUG	Registering shutdown blocker for GMPProvider
1500934979866	addons.manager	DEBUG	Provider finished startup: GMPProvider
1500934979866	addons.manager	DEBUG	Starting provider: PluginProvider
1500934979866	addons.manager	DEBUG	Registering shutdown blocker for PluginProvider
1500934979866	addons.manager	DEBUG	Provider finished startup: PluginProvider
1500934979866	addons.manager	DEBUG	Completed startup sequence
1500934980076	addons.manager	DEBUG	Starting provider: <unnamed-provider>
1500934980076	addons.manager	DEBUG	Registering shutdown blocker for <unnamed-provider>
1500934980077	addons.manager	DEBUG	Provider finished startup: <unnamed-provider>
1500934980142	DeferredSave.extensions.json	DEBUG	Starting write
1500934980221	addons.repository	DEBUG	No addons.json found.
1500934980221	DeferredSave.addons.json	DEBUG	Save changes
1500934980224	DeferredSave.addons.json	DEBUG	Starting timer
1500934980232	addons.manager	DEBUG	Starting provider: PreviousExperimentProvider
1500934980232	addons.manager	DEBUG	Registering shutdown blocker for PreviousExperimentProvider
1500934980232	addons.manager	DEBUG	Provider finished startup: PreviousExperimentProvider
1500934980233	DeferredSave.extensions.json	DEBUG	Write succeeded
1500934980233	addons.xpi-utils	DEBUG	XPI Database saved, setting schema version preference to 17
1500934980291	DeferredSave.addons.json	DEBUG	Starting write
1500934980298	DeferredSave.addons.json	DEBUG	Write succeeded

[snowymike]

is there a released selenium version with this fix? i'm on 3.5.3 using the legacy Firefox driver and i still see all the printouts discussed in this PR. the comments in #4362 suggest this issue has been fixed.

[biligunb]

@snowymike I did some workaround If you are interested.
Start the gecko driver from cmd line in your code with arguments --log fatal

That way gecko driver logs disappear. But the caveat is there will be cmd prompt running as long as the tests are running.

[barancev]

Yep, this issue was closed by mistake, it's related to legacy FirefoxDriver

[snowymike]

@biligunb thanks, but in my case i'm using the legacy firefox driver. just upgraded to 3.5.3 selenium in prep for later transitioning to gecko, but not there yet.

@barancev thanks for reopening. if there is any workaround while awaiting a production fix please let me know. i don't require any logging from the firefox driver, so a "turn everything off" workaround is all i'd need.

[jhmoore]

Huh, weird. Removing the -vv argument in that commit fixed the issue for us.

[snowymike]

@jhmoore in which selenium-java version is that -vv fix? in case it's relevant, i'm still on firefox 47.0.1. this selenium upgrade is step 1 of (hopefully) transitioning to gecko driver.

[lmtierney]

@snowymike the -vv fix will only work if you're using geckodriver

[snowymike]

is it likely we'll get a fix for this? i upgraded to selenium 3.5.3 in prep for switching to geckodriver, but i still see plenty of issues getting our code to work with geckodriver (e.g. clicks that work in chrome/ie/legacy firefox aren't working in geckodriver) that will likely take me quite a bit of time to work through. if we're able to fix this log issue for the legacy firefox driver that'd be great.