[🚀 Feature]: Selenium Command Logging across bindings

[titusfortner]

Feature and motivation

Ruby has a great logging implementation, that allows us to easily output warnings, deprecations and for users to toggle level to get things like command path, payload, and header info.

I believe that some of this functionality is available in other bindings, but we don't have it well documented how to toggle it. The solutions need to be language idiomatic, but I'm hoping we can ensure relatively equivalent functionality with this.

Usage example

In Ruby a user can do this to get all info about commands sent to and from the driver or server

Selenium::WebDriver.logger.level = :info

[github-actions[bot]]

@titusfortner, thank you for creating this issue. We will troubleshoot it as soon as we can.

---

Info for maintainers

Triage this issue by using labels.

If information is missing, add a helpful comment and then I-issue-template label.

If the issue is a question, add the I-question label.

If the issue is valid but there is no time to troubleshoot it, consider adding the help wanted label.

If the issue requires changes or fixes from an external project (e.g., ChromeDriver, GeckoDriver, MSEdgeDriver, W3C), add the applicable G-* label, and it will provide the correct link and auto-close the issue.

After troubleshooting the issue, please add the R-awaiting answer label.

Thank you!

[symonk]

all logging is accessible via the selenium hierarchical logger on the python side; whatever a client/user decides to do with that logger is entirely up to them; getting consistent logging across the languages tho could be beneficial, i've been logging things I deem to be useful for debugging issues.

Heres an example on the python side:

from selenium.webdriver.chrome.webdriver import WebDriver
from webdriver_manager.chrome import ChromeDriverManager

import logging

# trivial example of routing selenium logs to stdout.
selenium_logger = logging.getLogger("selenium")
selenium_logger.setLevel(logging.DEBUG)
selenium_logger.addHandler(logging.StreamHandler())

# Note: using a service/options instance is preferred here nowadays; passing an executable path is deprecated
with WebDriver(ChromeDriverManager().install()) as driver:
    driver.get("https://www.google.com")

will write to stdout:

...
POST http://localhost:59989/session/2acaff9914763cd413d5a066c8e1ad90/url {"url": "https://www.google.com"}
Remote response: status=200 | data={"value":null} | headers=HTTPHeaderDict({'Content-Length': '14', 'Content-Type': 'application/json; charset=utf-8', 'cache-control': 'no-cache'})
...
...

Outside of adding a NullHandler to the hierarchical selenium logger I think we leave it upto the clients to sort, its an application-wide task, however having consistent logging throughout the bindings would be a great idea I think

[symonk]

@titusfortner how do we drive this one on a little? adding some additional logging on the python side is possibly a quick win

[titusfortner]

@symonk yes, this is what I wanted to document.

I'm wondering if we can wrap this behavior and if it will address the issues below.

I'm thinking something like this:

webdriver.Logger(level=10, location=sys.stdout)

or

webdriver.Logger(level=logging.DEBUG, location='path/to/log.txt')

Issues:

1. Encapsulation

looks like Python implementation is coming from this:

LOGGER = logging.getLogger(__name__)

which I think means that *any time you create any logger you get that info. Is it possible to set it to toggle for just Selenium logs?

2. Consistency

Played around a bit & this matches what Ruby uses

    selenium_logger = logging.getLogger("selenium")
    selenium_logger.setLevel(logging.DEBUG)
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(logging.Formatter("%(asctime)s %(levelname)s Selenium %(message)s", 
                                           "%Y-%m-%d %H:%M:%S"))
    selenium_logger.addHandler(handler)

3. Levels

Ruby logs all input/output for commands to INFO instead of DEBUG Ruby uses DEBUG for everything else that is more chatty.

4. Deprecations, etc

Ruby turns on logging automatically at the WARN level then uses WARN to set deprecation notices One of the cool things we've done is to tag each warning with an id that can be turned off separately:

Selenium::WebDriver.logger.ignore(:timeout_opts)

Python has warnings.warn(), though and that's probably better than implementing this.

[titusfortner]

The first step here is to determine what it takes in each language right now to get logging information about what Selenium is doing under the hood and add it to the documentation —  https://www.selenium.dev/documentation/webdriver/troubleshooting/logging/

Once we see what can be done in each language we can make a more concrete plan of how to get equivalent information from each, etc.

[TamsilAmani]

@titusfortner & @pujagani. Let me know if any other aspect needs to be added. I have referred to the ruby logging documentation (in the above comment) and tried to keep it as close as possible.

LOGGING IN JAVASCRIPT:

JS has implemented logging APIs. It has also added LogManager to maintain a collection of loggers.

1. Getting a logger in JS can be done in two ways:

   const logging = require('selenium-webdriver/lib/logging')

   First method using manager

   mgr = new logging.LogManager()
   logger = mgr.getLogger('')
   

   Second method without manager

   logger = logging.getLogger('')

   Loggers class uses hierarchical, dot-delimited namespaces (e.g. "" > "webdriver" > "webdriver.logging"). For example, the following code will give a hierarchy of loggers:

   logger = mgr.getLogger('foo.bar.baz')

   "" (parent of) > "foo" (parent of) > "foo.bar" (parent of) > "foo.bar.baz" (=logger)

2. Logger Level:

   The basic levels for JS loggers are: OFF, SEVERE, WARNING, INFO, DEBUG, FINE, FINER, FINEST, ALL. To log messages at the given level pass the level in the log() method:

   logger.log(logging.Level.INFO, 'This is an info message')

   You can also use the instance methods to target logs of a particular level:

   logger.finest('this is the finest message')
   logger.finer('this is a finer message')
   logger.info('this is an info message')
   logger.warning('this is a warning message')
   logger.severe('this is a severe message
   

   By default the logger's level is Level.OFF To change the level of the logger:

   logger.setLevel(logging.Level.INFO)

3. Log Output:

   As opposed to ruby which by default sends logs to console in stdout, JS has the option to add a handler. The handler will be invoked for each message logged with this instance, or any of its descendants.

   logger.addHandler(callback)

   JS has provided a method to add console handler to the given logger. The console handler will log all messages using the JavaScript Console API:

   logging.addConsoleHandler(logger)

   Similarly, to add console handler to the root logger:

   logging.installConsoleHandler()

4. Logging Preference (remote logging API):

   JS gives the ability to define log preference for a remote WebDriver session. There are 5 common log types: BROWSER, CLIENT, DRIVER, PERFORMANCE, SERVER

   To set a log level for a particular log type:

   let prefs = new logging.Preferences()
   prefs.setLevel(logging.Type.BROWSER, logging.Level.FINE)
   

[TamsilAmani]

LOGGING IN PYTHON:

Selenium has not implemented any customised logging for python binding. So we are dependent on the 'logging' module of python.

1. Getting a logger in Python:

   import logging
   logger = logging.getLogger("selenium")
   

2. Logger Level:

   There are 6 build-in levels for logging module: NOTSET, DEBUG, INFO, WARNING, ERROR, CRITICAL To log messages at the given level pass the level in the log() method.

   logger.log(logging.DEBUG, 'This is a debug message')

   You can also use the in-built methods to target logs of a particular level.

   logger.info('this is a info message')
   logger.debug('this is a debug message')
   logger.warning('this is a warning message')
   logger.error('this is an error message')
   logger.critical('this is a critical message')
   

   By default the logger's level is WARNING (means that only events of this level and above will be tracked, unless the logging package is configured to do otherwise.) To change the level of the logger:

   logger.setLevel(logging.DEBUG)

   Python logs requests/response at DEBUG level as compared to ruby which logs them at INFO level

3. Log Output:

   Python has different handlers to log messages to differnt outputs: StreamHandler() - to log to console FileHandler() - to log to a file SocketHandler(), DatagramHandler(), etc

   To log messages on console stdout:

    handler = logging.StreamHandler(sys.stdout)
    logger.addHandler(handler)
   

   To log messages to a file:

    handler = logging.FileHandler('/path/to/selenium.log')
    logger.addHandler(handler)
   

   CONSISTENCY

   The output format for a log in ruby is:

    2023-02-05 02:34:48 INFO Selenium -> POST session/959be2d62f4dc10c53f4c28a28e0484c/url
    2023-02-05 02:34:48 INFO Selenium    >>> http://127.0.0.1:9515/session/959be2d62f4dc10c53f4c28a28e0484c/url | {"url":"https://www.google.com"}
   

   We can achieve a similar output format in python using setFormatter() on our handler:

    handler.setFormatter(logging.Formatter("%(asctime)s %(levelname)s Selenium -> %(message)s", 
                                       "%Y-%m-%d %H:%M:%S"))
   

   The output format for a log in python now is:

    2023-02-05 02:45:22 DEBUG Selenium -> POST http://localhost:53442/session/08540d8d39b4b7068787d422d79314e0/url {"url": "https://www.google.com"}                                       
   

4. Deprecations:

   In python we can use warnings.warn() to set deprecation notices, similar to ruby. Also, ruby tags the warnings with an 'id' that can be used to turn off the warning separately: A similar approach can be used in python using filterwarnings():

    import warnings
   
    warnings.filterwarnings('ignore', '.*do not.*', )
   
    # displayed warining
    warnings.warn('This wanring is visible')
   
    # this warning will not be displayed
    warnings.warn('Do not show this message')
   

[TamsilAmani]

LOGGING IN JAVA:

Java provides a log interface to get logs of a given type.

1. Log Levels:

   The supported log levels are the ones defined in 'java.util.logging.Level' package. These are:

   Level.ALL Level.FINE Level.INFO Level.WARNING Level.SEVERE Level.OFF

   In Java, DEBUG logs are mapped to INFO logs.

   Also, there are 6 LogTypes defined: BROWSER, CLIENT, DRIVER, PERFORMANCE, PROFILER, SERVER.

2. Getting the logs:

   Java has defined LoggingPreferences class to set the reqired logs:

   ChromeOptions chromeOptions = new ChromeOptions();
   LoggingPreferences logPrefs = new LoggingPreferences();
   logPrefs.enable(LogType.DRIVER, Level.INFO);
   chromeOptions.setCapability(ChromeOptions.LOGGING_PREFS, logPrefs);
   WebDriver driver = new ChromeDriver(chromeOptions);
   

   Use enable() to set the 'LogType' and 'Level' of the logs to be captured.

   To get the generated logs:

   driver.get("http://www.google.com");
   LogEntries logEntries = driver.manage().logs().get(LogType.DRIVER);
   

   LogEntries is an iterable object which is collection of LogEntry:

   for (LogEntry entry : logEntries) {
           System.out.println(entry.toString());
   }
   

   This gives a similar output as ruby:

   [2023-02-07T22:08:36.626Z] [INFO] [98336a0825efcef2657ec124809fbf61] COMMAND Navigate {
   		"url": "http://www.google.com"
   }
   
   [2023-02-07T22:08:37.425Z] [INFO] [98336a0825efcef2657ec124809fbf61] RESPONSE Navigate
   

3. Deprecations:

   Java uses Deprecated annotation to deprecate a class, method or a field. It also use the @deprecated Javadoc tag to tell developers what to use instead.

[pujagani]

@TamsilAmani Appreciate the detailed overview for each language. I think it can help document what is present better based off of your findings above. Pardon my limited knowledge of this section of the codebase, do among different languages, do all of them have the required logging features? Is there something missing that needs to be added to achieve parity? or is it a case of documenting the usage only?

[titusfortner]

I like what I get from the Ruby logs. Logging in other languages is less complete, and I would like to be able to see similar things implemented.

When I take this script, and "turn on logging" as described in the gist, this is what I'm getting as output:

https://gist.github.com/titusfortner/ef2b4c4d3ebc32dd91e44d55c2d5d2d5

You can see that the Java logging here is not exactly helpful to anyone.

[titusfortner]

With the updated filters for Java (Logger.getLogger(RemoteWebDriver.class.getName()).setLevel(Level.FINE);), I think we're essentially good for Java.

So, I think that means we can update https://www.selenium.dev/documentation/webdriver/troubleshooting/logging/ with Java, Python & JS details?

[titusfortner]

I'm going to consider this issue good now that we have everything better documented, the only thing missing is .NET and I created #12729 to track that.

[github-actions[bot]]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.