Selenium error log

Support the Selenium Project

Want to support the Selenium project? Learn more or view the full list of sponsors.

Logging in WebDriver

(Still under work)

Logging is important both for developers and users of WebDriver. Users might need to be able to find details about why a test failed, while developers might need to be able to find details of why WebDriver in itself failed. Good logging support can make these debugging tasks much easier.

Log Types

WebDriver may be used in different kinds of configurations. For instance, a client running a test may be connected directly to a a driver controlling a browser, or a client may be connected indirectly to a driver via a server. Depending on the configuration different kinds of logs may be available. With this in mind, the system should provide means to query for available log types.

In general, to debug a certain configuration it is useful to have access to logs from each of the nodes in the configuration. That is, from the client, server, driver, and the browser. Still, logs for all these nodes may not be available in all configurations. The server log being the simple example, but logs may also not be supported, or possible to retrieve due to the browser. In addition, there may be more logs available than the mentioned baseline. For instance, there may be support for logs specifically collecting performance data.

The known log types are:

For more information on which command to use to retrieve available log types, and a baseline of general log types, please view the wire protocol.

Logs

A log corresponds to a list of log entries, where each log entry is a tuple containing a timestamp, a log level, and a message.

Log Levels

The purpose of log levels is to provide a means to filter the messages in the log based on level of interest. For instance, if the purpose is debugging then more or less all messages may be of interest, while if the purpose is general monitoring then less information may be needed.

For WebDriver the following log levels have been selected (ordered from highest to lowest):

• OFF: Turns off logging
• SEVERE: Messages about things that went wrong. For instance, an unknown command.
• WARNING: Messages about things that may be wrong but was handled. For instance, a handled exception.
• INFO: Messages of an informative nature. For instance, information about received commands.
• DEBUG: Messages for debugging. For instance, information about the state of the driver.
• ALL: All log messages. A way to collect all information regardless of which log levels that are supported.

Languages like Java and Python typically provide a logging API with its own log levels, each with a name and a number, while the WebDriver log levels described above are described with names in a certain order (and no numbers). Driver implementors may use the log levels of their host language, but should translate the log levels of the host language to WebDriver log levels before sending logs over the wire.

Please see the wire protocol for more details.

Log Message

In general, a log message is just a string. Still, some log types may have a need for more structured information, for instance, to separate between different kinds of log messages. For such log types, the message part of a log entry may be structured as a JSON object. For cases where this is the practice it should be clear from the documentation.

Retrieval of Logs

Provided that a log type is supported, it should be possible to retrieve the corresponding log. For remote logs on a different node, retrieval involves the use of the wire protocol. In the scenario where a log is retrieved several times the same log entries should not be retrieved more than once. For this reason, and to same memory, after each retrieval of a log the log buffer of that log is reset.

Please see the wire protocol for more details.

Configuration of Logging Behavior

There may be cases where logging should be turned off entirely, or the number of logged messages should be fewer. For instance, a driver may be running on a device with limited resources. To support such cases it should be possible to configure logging behavior as a capability. A logging configuration of this kind corresponds to a list of pairs where log types are mapped to log levels. Since OFF is included as a log level a means for turning off logging is provided.

The default behavior should be to collect all log messages and let the client do filtering as needed. For cases where a different log level has been configured for a log type, messages under that log level should not be collected.

Please see the capabilities page for more information about logging configuration.

Browser Specific Behavior

Firefox

Merging of the Browser and Driver Logs

The Firefox driver provides an additional capability to configure whether the browser and driver log should be merged. In practice, this means that the driver log entries are printed to the error console of the browser, in addition to being collected elsewhere.

The default behavior is to merge the logs, the reason being that the error console of the browser provides a simple way to get a merged graphical view of the joined logs.

Please see the capabilities page for more information about Firefox specific capabilities.

We shall discuss how to introduce logging to our tests and how logging is important. After execution of test cases if we want to know the failures and how the test execution has taken place, we look at the test reports. However, if we want to investigate why the failures have taken place we should have proper logging in our code.

Introduction to Logging in Python Tests

The logs should describe each step of the test script. So that in case of failures we can find the root cause of the failure easily. There should be a separate file maintained for the logging purpose. Any non-technical person like business analysts, manual test engineers and so on should be able to open the log file and understand which step of the test case failed and for what reason.

As per industry standards, the logging is followed in the below format:

<time stamp> : <Logging levels> : <test case name> : <Log message>

The timestamp of when the actual test step gets executed should be captured in the log file. The logging levels are of different types like DEBUG, INFO, WARNING, ERROR and CRITICAL.  The INFO logging level is used to message the purpose of the test step. The WARNING logging level is used to alert the user of a particular step. However it does not indicate a failure in the test step. If the expected result has not matched with the actual result [for example: failure in assertion], the ERROR logging level is used. If there is a test that is blocking the entire execution, then CRITICAL logging level is used. The DEBUG logging level is used to give debugging information useful for the developer.

The below image shows a sample log file with logging.

Conclusion: Thus we have discussed what logs are and its importance. For more details, you can refer to the link:

https://courses.rahulshettyacademy.com/courses/learn-selenium-automation-in-easy-python-language/lectures/13248498

In the next section we shall discuss the importance of Filehandler in logging.

Importance of Filehandler in Logging tests

To implement logging in Python, we have to import package logging by adding the statement import logging in our code. This is by default available with Python and we don’t have to download any external plugin for that.

Next we have to create an object of the logging class with the help of the getLogger method.

logger = logging.getLogger()

The logger object is responsible for all the loggings. In the log file, it is essential to have the test case name to get its corresponding log information. To capture the test case file name at the run time, we shall pass the argument __name__ to the getLogger method. In this way, the name gets printed in the log file. If the argument is omitted in the getLogger method, the root is printed in the log file.

logger = logging.getLogger(__name__)

Next we shall add the logging levels with the logger object. The ways to use the logging levels are described below.

• logger.debug(«A debug statement is executed») – to produce  DEBUG logging level along with the message A debug statement is executed in the log file.
• logger.info(«An information statement is executed») – to produce INFO logging level along with the message An information statement is executed in the log file.
• logger.warning(«A warning statement is executed») – to produce WARNING logging level along with the message A warning statement is executed in the log file.
• logger.error(«An error statement is executed») – to produce ERROR logging level along with the message An error statement is executed in the log file.
• logger.critical(«A critical statement is executed») – to produce CRITICAL logging level along with the message A critical statement is executed in the log file.

Now the logger object should have the knowledge of the location and the format of the log file where the logging levels along with their message needs to be captured. We shall then call the addHandler method with the help of the logger object.

There is FileHandler class [is a part of the parent logging package] that accepts the location of the log file as an argument. We shall then create a filehandler object of that class and pass that as an argument to the addHandler method. The filehandler object has the knowledge of the location of the log file.

fileHandler = logging.FileHandler(‘logfile.log’)

logger.addHandler(fileHandler)

Now we shall explore how to describe the format of the log file. For this we have to take help of the Formatter class [is a part of the parent logging package] that accepts the format in which the log file as an argument. There are multiple formats to capture the content of the log file. But here we shall discuss the mostly widely used industry standard format of the log file.

First to get the current date and time in the below format in Python, we have to pass the value as %(asctime)s.

Next to describe the logging level in the log file, we have to pass the value as %(levelname)s. Then the test case name or the test file name can be added to the log file by passing %(name)s as an argument to the Formatter class. Finally %(message)s is passed as argument to print the logging message.

To sum up, we shall pass the parameters — %(asctime)s, %(levelname)s, %(name)s and %(message)s one by one separated by : as arguments to the Formatter class.

logging.Formatter(«%(asctime)s :%(levelname)s : %(name)s :%(message)s»)

Our next task is to pass the Formatter class information to the logger object. For this we shall first store logging.Formatter in an object variable named formatter. We shall then call the setFormatter method with the help of the fileHandler object and pass the formatter object as an argument to that method.

fileHandler.setFormatter(formatter)

Thus our formatter object is now logically connected to the fileHandler object. This fileHandler object is connected to the logger object with the help of the addHandler method. So the logger object holds information of both the log file location and format in which logging information is to be captured.

Finally we have to set the level of logging in the log file. For that we shall call the setLevel method with the help of the logger object. Then pass the logging level as a parameter to that method.

Please note the logging levels follow the below hierarchy:

• DEBUG
• INFO
• WARNING
• ERROR
• CRITICAL

This means if we set the logging level to INFO, then all the logs from the INFO, WARNING, ERROR and CRITICAL shall get captured in the log file. If it is set to ERROR, only the ERROR and CRITICAL logs shall be reflected in the log file.

Code Implementation

import logging

def test_logDemo():

# to get the name of the test case file name at runtime

logger = logging.getLogger(__name__)

# FileHandler class to set the location of log file

fileHandler = logging.FileHandler(‘logfile.log’)

# Formatter class to set the format of log file

formatter = logging.Formatter(«%(asctime)s :%(levelname)s : %(name)s :%(message)s»)

# object of FileHandler gets formatting info from setFormatter #method

fileHandler.setFormatter(formatter)

# logger object gets formatting, path of log file info with addHandler #method

logger.addHandler(fileHandler) 

# setting logging level to INFO

logger.setLevel(logging.INFO)

# logging debug message with logger object

logger.debug(«A debug statement is executed»)

# logging info message with logger object

logger.info(«An information statement is executed»)

# logging warning message with logger object

logger.warning(«A warning message is executed»)

# logging error message with logger object

logger.error(«An error message is executed»)

# logging critical message with logger object

logger.critical(«A critical message is executed»)

Output:

A new file named logfile.log gets created in the project folder. The log file contains the date and time stamp, the logging levels, test case file name pytestDemo.test_p and the logging messages.

As we set the logging level to INFO, INFO, WARNING, ERROR and CRITICAL logging messages are captured. The DEBUG log message is skipped. This is as per the hierarchy of logging levels discussed.

Conclusion

Thus we have discussed the importance of Filehandler in logging in Python. For more details, you can refer to the links:

https://courses.rahulshettyacademy.com/courses/learn-selenium-automation-in-easy-python-language/lectures/13248501

https://courses.rahulshettyacademy.com/courses/learn-selenium-automation-in-easy-python-language/lectures/13248503

https://courses.rahulshettyacademy.com/courses/learn-selenium-automation-in-easy-python-language/lectures/13248505

In the next post, we shall discuss how to interact with excel in Python.

Recently I’ve been writing Selenium tests for a large web application. The tests cover the most important features, and the suite grows nicely, but some flaky tests causing much pain and making the progress slower.

While investigating the problematic scenarios I’ve found that in many cases errors arise in the browser when a test randomly fails. Moreover, many passing tests also produce Javascript errors occasionally. In the latter cases the bug not surface in the test, but might cause problems later on.

These random errors are best eliminated, so I decided to add checks to detect client side log messages.

Detecting browser log messages

I considered two ways of reading client side log entries:

• Using the Selenium’s built in mechanism via DesiredCapabilities to query log messages.
• Injecting a Javascript agent after every page load to the application under test that tracks errors and log messages.

There are many other ways of doing this, like opening the developer console and taking a screenshot of it or using a custom browser plug-in, but this time I’ve tried to keep things simple. I also did not want to modify the application’s error handling for the sake of the tests.

Using DesiredCapabilities

Reading the logs via Selenium API is reliable and simple. All it takes is to instantiate the WebDriver with the proper settings.

LoggingPreferences logs = new LoggingPreferences();
logs.enable(LogType.BROWSER, Level.SEVERE);

DesiredCapabilities desiredCapabilities = DesiredCapabilities.firefox();
desiredCapabilities.setCapability(CapabilityType.LOGGING_PREFS, logs);

WebDriver driver = new FirefoxDriver(desiredCapabilities);

Then check the log messages:

LogEntries logEntries = driver.manage().logs().get(LogType.BROWSER);

for (LogEntry logEntry : logEntries) {
	// Get log message, timestamp and level.
}

Unfortunately, the only important information I was able to get through this API is the log message, not the line numbers or the stack traces. On the plus side, all error messages — including the ones during page load — can be acquired.

Testing small or extremely deterministic applications this might be enough, as simply reproducing the steps manually will bring forth the bug with all the relevant technical data.

Using a Javascript agent

Of course, errors contain much more information than just a message. One way to work around the problem with the previous method is to capture the exceptions in the browser. This can be a bit brittle and cumbersome, because it needs an agent to track errors and log messages and provide a way to query them. If the agent is subject to some kind of abuse, it might sabotage the log recording or even break the tests. Because I didn’t want to modify the system under test, I inject the agent to the browser after every page load. This means the agent is unable to provide information about errors that occurred before the page is completely loaded.

The agent can be injected with the executeScript method provided by the JavascriptExecutor interface.

The Javascript code of the agent can be something like this:

(function() {
	if (window.logEvents) return;

	function captureUnhandled(errorMsg, url, lineNumber, column, errorObj) {
		var logMessage = new Date() + ' unhandled - ' + errorMsg + ', ' + errorObj.stack;
		window.logEvents.push(logMessage);
	}

	function capture(level) {
		return function() {
			var args = Array.prototype.slice.call(arguments, 0);
			var logMessage = new Date() + ' ' + level + ' - ';
			for(var i=0; i<args.length; i++) {
				if (args[i] instanceof Error) {
					logMessage += args[i].message + ', ' + args[i].stack;
				} else {
					logMessage += args[i];
				}
			}
			window.logEvents.push(logMessage);
		}
	}
	console = console || {};
	console.warn = capture('warn');
	console.error = capture('error');
	window.onerror = captureUnhandled;
	window.logEvents = [];
}());

As you can see, the agent keeps track of not only the errors and log messages, but also preserves the associated stack traces. For practical reasons the agent above can be injected many times to the same page without causing any problems. This is handy, because it eliminates the need to keep track whether the script is already injected or not.

The captured events can be checked easily with the following code:

	List<String> logEvents = (List<String>) ((JavascriptExecutor)driver).executeScript("return window.logEvents;");
	
	for (String logEvent : logEvents) {
		// The logEvent String contains all collected information.
	}

Making assertions and reports from client side logs

Because each method has some drawbacks, I use them both. Right now I just store the client side log information in the Cucumber test report to aid manual inspection of the failing tests, but it could be used to assert that there are no exceptions in the Javascript application during the tests.

This approach has some limitations though, as it can work properly for testing one page applications only. When a test scenario performs an action that leads to another webpage, all previously collected data simply vanish with the fresh page load.