Hot to log Selenium Grid2 into a database

Selenium logs

Some time ago we switched Nerrvana to Selenium Grid2. Now you can launch both Selenium 1 and WebDriver tests. The other thing that pushed us to do so is a dramatic improvement of Selenium’s work with the browsers.

From the very beginning we decided not to hide but share our findings in building Nerrvana so it can be used if you decide to build a Selenium cloud on your own or just to help you solve some problems you face.

One of the problems I faced while moving Nerrvana to Selenium Grid2 was to push Selenium logs into a database.

Why did we need it?

First, monitoring Selenium logs allows detecting if Selenium node/RC is in a healthy state.
Second, we can use logs to find out if tests still work with a browser. If tests were launched but we have no entries coming to a log – this is an indication that tests may be hung or failed due to incorrect configuration etc.
Third, we use notes from logs to display messages generated by tests in real time in Nerrvana’s UI.
It was quite easy to set logging to database in Selenium 1. You just add the log4j library in classpath and set log4j configuration path in log4j.configuration parameter when a RC is launched.

In the configuration file you can set log4j to write log to database. That’s it.

However we found that same method does not work with Selenium 2. Now the Grid uses “standard” ways for logging. Besides different Selenium parts use different logging methods. And it is not surprising, since there are some problems with logging standards in Java.

Those logs that interested me are written using java.util.logging. As I understood by googling it, sending logs from JUL to the DB directly is not an easy thing to do. A list of “handlers” for JUL is much less pleasant than a list of appenders for log4j.

However, we found our saving grace – slf4j. This library provides a common interface for working with various loggers, such as log4j. The best part is that slf4j allows you to create “bridges” between other systems’ logging components and itself. That is, some module will write the logs, using, for example, java.util.logging, and the logs will really get into the slf4j, and be sent to another logger.

In order to turn on a “bridge” we do not need to change our code. We can simply include the required jar from slf4j jar to the classpath and maybe change a couple of system properties.
Well, that’s exactly what we needed!

I figured out how slf4j works and tested it on simple examples, and began using it for Selenium Grid 2.
Let me warn you, I did not manage to make it work. I note that I am not a great expert in Java, so it would be cool if someone said – oh, yes there you have extra space, remove it and it will work.

Now I will describe what I did, and how I did it.

I used the selenium-server-standalone-2.23.1.jar, slf4j-1.6.6.zip, log4j-1.2.17.zip.

I experimented with a Selenium node (because I was looking for its logs in the first place). During the experiments, a Selenium hub was also launched.

To redirect jul logging to slf4j, you must specify bridge to slf4j as a handler in the jul configuration file logging.properties:

handlers = org.slf4j.bridge.SLF4JBridgeHandler

The file itself can be specified using the system property java.util.logging.config.file:

-Djava.util.logging.config.file=C:/test/logging.properties

Next you need to add the following jar’s in the classpath:

- jul-to-slf4j-1.6.6.jar // includes SLF4JBridgeHandler
– slf4j-api-1.6.6.jar // slf4j itself
– slf4j-log4j12-1.6.6.jar // redirects logs to log4j
– log4j.jar // log4j itself
– log4j.xml // log4j configuration file

Now we try to start a node, using all our knowledge gained to this point, with the following command:

java -classpath c:/test/slf/jul-to-slf4j-1.6.6.jar;c:/test/slf/slf4j-api-1.6.6.jar;^
c:/test/slf/slf4j-log4j12-1.6.6.jar;c:/test/log4j.jar;c:/test/log4j.xml; ^
-Djava.util.logging.config.file=C:/test/logging.properties ^
-jar selenium-server-standalone.jar -role node ^
-hub http://localhost:4444/grid/register

Result:

Can't load log handler "org.slf4j.bridge.SLF4JBridgeHandler"
java.lang.ClassNotFoundException: org.slf4j.bridge.SLF4JBridgeHandler

Excellent! Apparently, jul-to-slf4j-1.6.6.jar which contains a not found class somehow did not become available in time to jul.

UPDATE 16.02.2013


In the comments stackedsax pointed to my mistake which was the reason of the fail. To use given classpath there should not be -jar. Therefore, to use сlasspath, we should add selenium server to classpath and launch the org.openqa.grid.selenium.GridLauncher directly.

Below is the corrected command (with current versions of libraries):

java -classpath c:/test/selenium-server-standalone.jar;^
c:/test/jul-to-slf4j-1.7.2.jar;c:/test/slf4j-api-1.7.2.jar;^
c:/test/slf4j-log4j12-1.7.2.jar;c:/test/log4j-1.2.17.jar;c:/test/log4j.xml; ^
-Djava.util.logging.config.file=C:/test/logging.properties ^
org.openqa.grid.selenium.GridLauncher -role node ^
-hub http://localhost:4444/grid/register

All the logs are redirected to log4j, and it is easy now to write them to the database using an appropriate appender now.
In stackedsax's post you can read about writing selenium logs using the same method to logstash.

Simple log4j.xml to write to file and stdout::

<?xml version="1.0" encoding="UTF-8" ?>
 <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration debug="false" xmlns:log4j='http://jakarta.apache.org/log4j/'>
    <appender name="file" class="org.apache.log4j.RollingFileAppender">
        <param name="File" value="C:/test/hub_file_log.txt" />
        <param name="MaxFileSize" value="10240KB"/>
        <param name="MaxBackupIndex" value="10" />
        <param name="Append" value="false" />
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d{yyyyMMdd HH:mm:ss} %-5p - %m%n"/>
        </layout>
    </appender>
    <appender name="stdout" class="org.apache.log4j.ConsoleAppender">
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d{yyyyMMdd hh:mm:ss} %-5p %M(%C{1}:%L) - %m%n"/>
        </layout>
    </appender>
    <root>
        <priority value ="info" />
        <appender-ref ref="file" />
        <appender-ref ref="stdout" />
    </root>
</log4j:configuration>

The previous method with Ant as a wrapper below is working too, but now there is no sense to use it anymore, so you can stop reading here.


End of UPDATE

Ok, let’s repeat this, but using Ant.

build.xml:

<project name="dslabs-test" default="" basedir=".">
    <path id="node_classpath">
        <fileset dir="${basedir}">
            <include name="jul-to-slf4j-1.6.6.jar"/>
            <include name="slf4j-api-1.6.6.jar"/>
            <include name="slf4j-log4j12-1.6.6.jar"/>
            <include name="log4j.jar"/>
            <include name="log4j.xml"/>
            <include name="selenium-server-standalone.jar"/>
        </fileset>
    </path>
    <target name="node">
        <java classpathref="node_classpath"
            fork="true"
            classname="org.openqa.grid.selenium.GridLauncher"
            failonerror="false">
            <arg line="-role node -hub http://localhost:4444/grid/register" />
            <sysproperty key="java.util.logging.config.file" value="C:/test/lib/logging.properties"/>
        </java>
    </target>
</project>

Yeah, now, instead of "... Registering the node to hub ..." we see these errors

java.lang.NoSuchMethodError: org.slf4j.Logger.isTraceEnabled()Z
at org.apache.commons.logging.impl.SLF4JLog.isTraceEnabled(SLF4JLog.java:86)
at org.openqa.jetty.http.HttpServer.service(HttpServer.java:893)

Google "knows" a lot about this issue and, in general, it is an incompatibility between versions of slf4j libraries.
As far as I was able to determine, Grid2 does not have slf4j. I dug more, tried to redirect the logs from those parts of the Grid, which use jcl - roughly with the same result.
Then I realized that it can take a long time trying to solve my problem along this path. I began to look towards alternative solutions - in other words, the crutches.

In general, the choice was between a pair of old ideas:
- Abandon the idea of real time logging to a database. Write to the log file and parse it upon test completion to extract user’s messages.
- Send Selenium output to syslog, and use it to write to the database

The first idea: for a rainy day.
The second idea - most likely will have a relatively long implementation time. I've never worked with syslog/rsyslog. I’m afraid of hidden traps going this path and I really like log4j’s flexibility.

In the end, until better times, when Selenium developers will change logging subsystem, or I will find time to fix slf4j issues, I decided to use the crutches in the form of ant.
It is very easy to configure Ant to send logs via log4j. Thus, we launch Selenium Node from Ant, which will receive output from the Selenium node and write it to the database through log4j we know and like.

Here is how it looks:
build.xml

<project name="dslabs-test" default="" basedir=".">
    <path id="node_classpath">
        <fileset dir="${basedir}">
            <include name="selenium-server-standalone.jar"/>
        </fileset>
    </path>
    <target name="node">
        <java classpathref="node_classpath"
            fork="true"
            classname="org.openqa.grid.selenium.GridLauncher"
            failonerror="false">
            <arg line="-role node -hub http://localhost:4444/grid/register" />
        </java>
    </target>
</project>

Created a convenient start_node.bat:

@ECHO OFF
ant -listener org.apache.tools.ant.listener.Log4jListener -Dlog4j.configuration=file:"C:/test/log4j.xml" ^
-lib C:/test/log4j.jar -lib C:/test/postgresql.jdbc3.jar -lib C:/test/jdbcappender.jar node
exit 0

Put the required JARs and log4j.xml in the folder C:/test, launch a hub, and run start_node.bat. A node is running, logs from Selenium are getting into Ant from where log4j writes them to a database.

Of course, such approach has its own drawbacks:
- Uses an additional component - Ant
- This component, besides the cost of log translation, takes a decent chunk of RAM
- Loss of flexibility in logging - you cannot filter out logs at the starting point - Selenium node. You cannot format them how you want.

Given the fact that Selenium writes logs sparingly (it takes more time to wait for pages to load) this approach can be used and this is what we are doing.
It will be great if someone helps out with the errors I get with slf4j or point me in a right direction.
/a

Print this post | Home

3 comments

  1. stackedsax says:

    I think the only thing wrong with your pre-ant command line for starting selenium is that you can’t use -jar AND set your classpath.

  2. stackedsax says:

    I wrote something up: http://alexscammon.com/2013/02/sending-selenium-logs-to-logstash

    Let me know if it helps.

  3. bear says:

    stackedsax, you are right.
    As you wrote in your article, all I need is to change “-jar selenium-server-standalone.jar” to “org.openqa.grid.selenium.GridLauncher”.
    Damn!

    Thank you very much, I will remove ant and update this post too.