search

mozilla / geckodriver

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

There is no capability to set the browser log destination #414

Open barancev opened 7 years ago

barancev commented 7 years ago

There is no capability to set the browser log destination

andreastt commented 7 years ago

I don’t want to add complexity that can be handled at the binding level. What is the reason the binding cannot control this if it controls the lifetime of the process?

barancev commented 7 years ago

A binding does not control the browser lifecycle, it does not start the browser (the driver server does) and can't handle its output directly

andreastt commented 7 years ago

geckodriver inherits Firefox’s output, and a client binding in many cases doubles as the owner of the driver process. But regardless what point controls the process, log collation could be done by this entity without the involvement of the driver. What benefit does it give for geckodriver to write its own log file, versus the process that spawned it redirecting it to a file, if it’s a log on the file system that you want?

barancev commented 7 years ago

How to get the browser log currently? All I can get (from Java binding) at the moment is:

1483526010470   mozprofile::profile INFO    Using profile path C:\Users\alexei\AppData\Local\Temp\rust_mozprofile.qQGIXQ75gzZ7
1483526010480   mozprofile::profile INFO    Using profile path C:\Users\alexei\AppData\Local\Temp\rust_mozprofile.07VS5U0btY11
1483526010487   mozprofile::profile INFO    Using profile path C:\Users\alexei\AppData\Local\Temp\rust_mozprofile.9Zu53bYAkpWZ
1483526010489   geckodriver::marionette INFO    Starting browser C:\Program Files (x86)\Nightly\firefox.exe
1483526040814   geckodriver::marionette INFO    Connecting to Marionette on localhost:53838
1483526041450   Marionette  INFO    Listening on port 53838
янв 04, 2017 1:34:02 PM org.openqa.selenium.remote.ProtocolHandshake createSession
INFO: Detected dialect: W3C
1483526042969   Marionette  INFO    New connections will no longer be accepted

Will option -v add there the browser logs?

andreastt commented 7 years ago

The lines you see that start with “Marionette” come from the browser. Those starting with “geckodriver” or “mozprofile” come from various Rust code. In other words, all output from the Firefox process is redirected to geckodriver’s stdout.

The code that is responsible for this can be found in https://github.com/mozilla/geckodriver/blob/master/src/logging.rs#L121-L145 and https://github.com/jgraham/rust_mozrunner/blob/master/src/runner.rs#L114-L118.

barancev commented 7 years ago

I wonder why I get a long browser log if I run "classic" FirefoxDriver (see below) and a short log when I run marionette (see above)?

1483552671661   addons.manager  DEBUG   Loaded provider scope for resource://gre/modules/addons/XPIProvider.jsm: ["XPIProvider"]
1483552671662   addons.manager  DEBUG   Loaded provider scope for resource://gre/modules/LightweightThemeManager.jsm: ["LightweightThemeManager"]
1483552671664   addons.manager  DEBUG   Loaded provider scope for resource://gre/modules/addons/GMPProvider.jsm
1483552671665   addons.manager  DEBUG   Loaded provider scope for resource://gre/modules/addons/PluginProvider.jsm
1483552671666   addons.manager  DEBUG   Starting provider: XPIProvider
1483552671666   addons.xpi  DEBUG   startup
1483552671667   addons.xpi  INFO    Mapping fxdriver@googlecode.com to C:\Users\alexei\AppData\Local\Temp\anonymous5543640396769943674webdriver-profile\extensions\fxdriver@googlecode.com
1483552671667   addons.xpi  DEBUG   Ignoring file entry whose name is not a valid add-on ID: C:\Users\alexei\AppData\Local\Temp\anonymous5543640396769943674webdriver-profile\extensions\webdriver-staging
1483552671667   addons.xpi  INFO    SystemAddonInstallLocation directory is missing
1483552671668   addons.xpi  INFO    Mapping loop@mozilla.org to C:\Program Files\Mozilla Firefox\browser\features\loop@mozilla.org.xpi
1483552671669   addons.xpi  INFO    Mapping {972ce4c6-7e08-4474-a285-3208198ce6fd} to C:\Program Files\Mozilla Firefox\browser\extensions\{972ce4c6-7e08-4474-a285-3208198ce6fd}.xpi
1483552671669   addons.xpi  DEBUG   Skipping unavailable install location app-system-share
1483552671669   addons.xpi  DEBUG   Skipping unavailable install location app-system-local
1483552671669   addons.xpi  DEBUG   checkForChanges
1483552671670   addons.xpi  DEBUG   Loaded add-on state from prefs: {}
1483552671670   addons.xpi  DEBUG   New add-on fxdriver@googlecode.com in app-profile
1483552671670   addons.xpi  DEBUG   getModTime: Recursive scan of fxdriver@googlecode.com
1483552671674   addons.xpi  DEBUG   New add-on loop@mozilla.org in app-system-defaults
1483552671674   addons.xpi  DEBUG   getModTime: Recursive scan of loop@mozilla.org
1483552671674   addons.xpi  DEBUG   New add-on {972ce4c6-7e08-4474-a285-3208198ce6fd} in app-global
1483552671675   addons.xpi  DEBUG   getModTime: Recursive scan of {972ce4c6-7e08-4474-a285-3208198ce6fd}
1483552671675   addons.xpi  DEBUG   getInstallState changed: true, state: {"app-profile":{"fxdriver@googlecode.com":{"d":"C:\\Users\\alexei\\AppData\\Local\\Temp\\anonymous5543640396769943674webdriver-profile\\extensions\\fxdriver@googlecode.com","st":1483552670801,"mt":1483552670796}},"app-system-defaults":{"loop@mozilla.org":{"d":"C:\\Program Files\\Mozilla Firefox\\browser\\features\\loop@mozilla.org.xpi","st":1481338232000}},"app-global":{"{972ce4c6-7e08-4474-a285-3208198ce6fd}":{"d":"C:\\Program Files\\Mozilla Firefox\\browser\\extensions\\{972ce4c6-7e08-4474-a285-3208198ce6fd}.xpi","st":1481338232000}}}
1483552671681   addons.xpi-utils    DEBUG   Opening XPI database C:\Users\alexei\AppData\Local\Temp\anonymous5543640396769943674webdriver-profile\extensions.json
1483552671682   addons.xpi-utils    DEBUG   New add-on fxdriver@googlecode.com installed in app-profile
*** Blocklist::_loadBlocklistFromFile: blocklist is disabled
1483552671697   DeferredSave.extensions.json    DEBUG   Save changes
1483552671697   addons.xpi-utils    DEBUG   New add-on loop@mozilla.org installed in app-system-defaults
1483552671702   DeferredSave.extensions.json    DEBUG   Starting timer
1483552671703   DeferredSave.extensions.json    DEBUG   Save changes
1483552671703   addons.xpi-utils    DEBUG   New add-on {972ce4c6-7e08-4474-a285-3208198ce6fd} installed in app-global
1483552671706   DeferredSave.extensions.json    DEBUG   Save changes
1483552671706   addons.xpi-utils    INFO    Hiding the updated system add-ons.
1483552671707   addons.manager  DEBUG   Registering startup change 'installed' for fxdriver@googlecode.com
1483552671707   addons.xpi-utils    DEBUG   Make addon app-profile:fxdriver@googlecode.com visible
1483552671707   DeferredSave.extensions.json    DEBUG   Save changes
1483552671713   addons.xpi  DEBUG   Loading bootstrap scope from C:\Program Files\Mozilla Firefox\browser\features\loop@mozilla.org.xpi
1483552671723   addons.xpi  DEBUG   Calling bootstrap method install on loop@mozilla.org version 1.1.14
1483552671723   addons.xpi-utils    DEBUG   Make addon app-system-defaults:loop@mozilla.org visible
1483552671723   DeferredSave.extensions.json    DEBUG   Save changes
1483552671724   addons.xpi-utils    DEBUG   Make addon app-global:{972ce4c6-7e08-4474-a285-3208198ce6fd} visible
1483552671724   DeferredSave.extensions.json    DEBUG   Save changes
1483552671724   addons.xpi  DEBUG   Updating XPIState for {"id":"fxdriver@googlecode.com","syncGUID":"nOyHVGWxDmr6","location":"app-profile","version":"3.0.1","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":"C:\\Users\\alexei\\AppData\\Local\\Temp\\anonymous5543640396769943674webdriver-profile\\extensions\\fxdriver@googlecode.com","installDate":1483552670801,"updateDate":1483552670801,"applyBackgroundUpdates":1,"bootstrap":false,"skinnable":false,"size":3278845,"sourceURI":null,"releaseNotesURI":null,"softDisabled":false,"foreignInstall":true,"hasBinaryComponents":true,"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}
1483552671724   addons.xpi  DEBUG   getModTime: Recursive scan of fxdriver@googlecode.com
1483552671727   addons.xpi  DEBUG   Updating XPIState for {"id":"loop@mozilla.org","syncGUID":"YlO1wpxTahSj","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":"C:\\Program Files\\Mozilla Firefox\\browser\\features\\loop@mozilla.org.xpi","installDate":1481338232000,"updateDate":1481338232000,"applyBackgroundUpdates":1,"bootstrap":true,"skinnable":false,"size":4109538,"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}
1483552671727   addons.xpi  DEBUG   getModTime: Recursive scan of loop@mozilla.org
1483552671728   addons.xpi  DEBUG   Updating XPIState for {"id":"{972ce4c6-7e08-4474-a285-3208198ce6fd}","syncGUID":"i1UQzvBH8Cto","location":"app-global","version":"45.6.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":"C:\\Program Files\\Mozilla Firefox\\browser\\extensions\\{972ce4c6-7e08-4474-a285-3208198ce6fd}.xpi","installDate":1481338232000,"updateDate":1481338232000,"applyBackgroundUpdates":1,"skinnable":true,"size":22012,"sourceURI":null,"releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"hasBinaryComponents":false,"strictCompatibility":true,"locales":[],"targetApplications":[{"id":"{ec8030f7-c20a-464f-9b0e-13a3a9e97384}","minVersion":"45.6.0","maxVersion":"45.6.0"}],"targetPlatforms":[],"seen":true}
1483552671728   addons.xpi  DEBUG   getModTime: Recursive scan of {972ce4c6-7e08-4474-a285-3208198ce6fd}
1483552671728   DeferredSave.extensions.json    DEBUG   Save changes
1483552671728   addons.xpi  DEBUG   Updating database with changes to installed add-ons
1483552671728   addons.xpi-utils    DEBUG   Updating add-on states
1483552671729   addons.xpi-utils    DEBUG   Writing add-ons list
1483552671731   addons.xpi  DEBUG   Registering manifest for C:\Program Files\Mozilla Firefox\browser\features\loop@mozilla.org.xpi
1483552671732   addons.xpi  DEBUG   Calling bootstrap method startup on loop@mozilla.org version 1.1.14
1483552671734   addons.manager  DEBUG   Registering shutdown blocker for XPIProvider
1483552671734   addons.manager  DEBUG   Provider finished startup: XPIProvider
1483552671734   addons.manager  DEBUG   Starting provider: LightweightThemeManager
1483552671734   addons.manager  DEBUG   Registering shutdown blocker for LightweightThemeManager
1483552671735   addons.manager  DEBUG   Provider finished startup: LightweightThemeManager
1483552671735   addons.manager  DEBUG   Starting provider: GMPProvider
1483552671740   addons.manager  DEBUG   Registering shutdown blocker for GMPProvider
1483552671740   addons.manager  DEBUG   Provider finished startup: GMPProvider
1483552671740   addons.manager  DEBUG   Starting provider: PluginProvider
1483552671740   addons.manager  DEBUG   Registering shutdown blocker for PluginProvider
1483552671741   addons.manager  DEBUG   Provider finished startup: PluginProvider
1483552671741   addons.manager  DEBUG   Completed startup sequence
1483552671958   addons.manager  DEBUG   Starting provider: <unnamed-provider>
1483552671958   addons.manager  DEBUG   Registering shutdown blocker for <unnamed-provider>
1483552671958   addons.manager  DEBUG   Provider finished startup: <unnamed-provider>
1483552672043   DeferredSave.extensions.json    DEBUG   Starting write
1483552672208   addons.repository   DEBUG   No addons.json found.
1483552672208   DeferredSave.addons.json    DEBUG   Save changes
1483552672211   DeferredSave.addons.json    DEBUG   Starting timer
1483552672219   addons.manager  DEBUG   Starting provider: PreviousExperimentProvider
1483552672219   addons.manager  DEBUG   Registering shutdown blocker for PreviousExperimentProvider
1483552672220   addons.manager  DEBUG   Provider finished startup: PreviousExperimentProvider
1483552672222   DeferredSave.extensions.json    DEBUG   Write succeeded
1483552672222   addons.xpi-utils    DEBUG   XPI Database saved, setting schema version preference to 17
1483552672393   DeferredSave.addons.json    DEBUG   Starting write
1483552672401   DeferredSave.addons.json    DEBUG   Write succeeded
andreastt commented 7 years ago

If you read that log carefully, I think they are a result of installing the FirefoxDriver add-on. It may trigger some more initialisation behaviour internally that causes some more addons to get registered. For example, I see a few references to fxdriver@googlecode.com there. The reference here should be what you see when you start Firefox from the shell.

andreastt commented 7 years ago

In your above output, the following lines come directly from Gecko/Firefox:

1483526041450   Marionette  INFO    Listening on port 53838
1483526042969   Marionette  INFO    New connections will no longer be accepted

https://github.com/mozilla/gecko-dev/blob/master/testing/marionette/components/marionette.js#L218 https://github.com/mozilla/gecko-dev/blob/master/testing/marionette/server.js#L79

whimboo commented 6 years ago

@barancev all those additional logging for add-ons will happen when the preference extensions.logging.enabled is set to True. Does the old FirefoxDriver do that? We don't do for geckodriver because it is not helpful information for normal testers.