Logging Selenium 2 Events in Twist

Limitations of using custom drivers

I’ve been using Selenium 2 quite heavily with Twist over the last couple of weeks, and a few things have been bothering me.  These things are mainly issues around not using a tightly integrated driver like Selenium 1 and Sahi.  For those drivers, ThoughtWorks have put in a great deal of effort in to handling configuration, logging, and various other niceties.  So not being one to let that hold our teams back from those things that are of value to them, I’ve started having a crack at spiking out a few solutions.  The first one being the handling of useful logging from the Selenium 2 driver.  Here’s the output from that spike.

Implementing a WebDriver event listener

It turns out that the Selenium 2 team have made life easy from the start on this one.  There is an listener interface that can be implemented against for hooking it to useful driver state information at key event firing points.  At this point, I just want to get up and running to have a play with what could be done.  So I just created a new class that implemented stubs against each method (which was required anyway as it was an abstract interface).  So that looked a little something like below.

package common.driver;

import org.openqa.selenium.By;
import org.openqa.selenium.WebDriver;
import org.openqa.selenium.WebElement;
import org.openqa.selenium.support.events.WebDriverEventListener;

public class MyWebDriverEventListener implements WebDriverEventListener {

	public void afterChangeValueOf(WebElement element, WebDriver selenium) {}
	public void afterClickOn(WebElement element, WebDriver selenium) {}
	public void afterFindBy(By by, WebElement element, WebDriver selenium) {}
	public void afterNavigateBack(WebDriver selenium) {}
	public void afterNavigateForward(WebDriver selenium) {}
	public void afterNavigateTo(String url, WebDriver selenium) {}
	public void afterScript(String script, WebDriver selenium) {}
	public void beforeChangeValueOf(WebElement element, WebDriver selenium) {}
	public void beforeClickOn(WebElement element, WebDriver selenium) {}
	public void beforeFindBy(By by, WebElement element, WebDriver selenium) {}
	public void beforeNavigateBack(WebDriver selenium) {}
	public void beforeNavigateForward(WebDriver selenium) {}
	public void beforeNavigateTo(String url, WebDriver selenium) {}
	public void beforeScript(String script, WebDriver selenium) {}
	public void onException(Throwable error, WebDriver selenium) {}

}

Hooking the event listener in to the driver

We already had a driver factory for managing Selenium 2 via Spring.  So it was then a case of hooking my event listener in to the driver within the factory class.  This was done by wrapping the existing driver with an event firing driver, and registering the event listener against it.  This ended up something like below (using a remote chrome driver in this instance).

package common.driver;

import java.net.URL;

import org.openqa.selenium.WebDriver;
import org.openqa.selenium.remote.DesiredCapabilities;
import org.openqa.selenium.remote.RemoteWebDriver;
import org.openqa.selenium.support.events.EventFiringWebDriver;
import org.openqa.selenium.support.events.WebDriverEventListener;

public class WebDriverFactory {

	private String remoteURL;
	private WebDriver selenium;
	private WebDriverEventListener eventListener;

	public WebDriverFactory(String remoteURL) {
		this.remoteURL = remoteURL;
		this.eventListener = new MyWebDriverEventListener();
	}

	public void start() {
		try {
			selenium = new EventFiringWebDriver(new RemoteWebDriver(new URL(remoteURL), DesiredCapabilities.chrome())).register(eventListener);
		} catch (Exception e) {
			throw new RuntimeException(e);
		} finally {
			//
		}
	}

	public void stop() {
		selenium.quit();
	}

	public WebDriver getSelenium() {
		return selenium;
	}
}

Plugging in a logging mechanism

Right, things were looking up at this point.  I could run scenarios without a hitch, but I wanted some logging output to see the fruits of my experiments.  So I gave myself a log to look with by using LogFactory from Apache Commons.  Quite simple to do by adding this single line in to the event listener class.

private Log log = LogFactory.getLog(this.getClass());

… and then adding the logger to the log4j.properties file in the Twist project.

# WebDriver event listener logger
log4j.logger.common.driver.LoggingWebDriverEventListener = DEBUG

Let the experiments begin

With the basic mechanical framework now in place, it was time to start having some fun with it.

Logging navigation

I started with something simple to prove the wiring.  An implementation of the before navigate to method.

	public void beforeNavigateTo(String url, WebDriver selenium){
		log.info("WebDriver navigating to:'"+url+"'");
	}

All this should do is log the URL being navigated to, and a high five was due because this was the output on executing an existing Twist scenario.

0    [pool-3-thread-1] INFO  common.driver.LoggingWebDriverEventListener  - WebDriver navigating to:'http://www.google.co.uk'

Now for something more useful for debugging in CI execution

The real benefit of logging to our teams is to give some extra diagnostic feedback when running scenarios in CI.  So at this point I set myself a few goals.

  • Trap driver exceptions
  • Provide useful contextual information
This was the first stab at doing that.
package common.driver;

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.openqa.selenium.By;
import org.openqa.selenium.NoSuchElementException;
import org.openqa.selenium.WebDriver;
import org.openqa.selenium.WebElement;
import org.openqa.selenium.support.events.WebDriverEventListener;

public class LoggingWebDriverEventListener implements WebDriverEventListener {

	private Log log = LogFactory.getLog(this.getClass());
	private By lastFindBy;
	private String originalValue;

	public void beforeNavigateTo(String url, WebDriver selenium){
		log.info("WebDriver navigating to:'"+url+"'");
	}

	public void beforeChangeValueOf(WebElement element, WebDriver selenium){
		originalValue = element.getValue();
	}

	public void afterChangeValueOf(WebElement element, WebDriver selenium){
		log.debug("WebDriver changing value in element found "+lastFindBy+" from '"+originalValue+"' to '"+element.getValue()+"'");
	}

	public void beforeFindBy(By by, WebElement element, WebDriver selenium){
		lastFindBy = by;
	}

	public void onException(Throwable error, WebDriver selenium){
		if (error.getClass().equals(NoSuchElementException.class)){
			log.error("WebDriver error: Element not found "+lastFindBy);
		} else {
			log.error("WebDriver error:", error);
		}
	}

	public void beforeNavigateBack(WebDriver selenium){}
	public void beforeNavigateForward(WebDriver selenium){}
	public void beforeClickOn(WebElement element, WebDriver selenium){}
	public void beforeScript(String script, WebDriver selenium){}
	public void afterClickOn(WebElement element, WebDriver selenium){}
	public void afterFindBy(By by, WebElement element, WebDriver selenium){}
	public void afterNavigateBack(WebDriver selenium){}
	public void afterNavigateForward(WebDriver selenium){}
	public void afterNavigateTo(String url, WebDriver selenium){}
	public void afterScript(String script, WebDriver selenium){}

}

So with those new method implementations, I caught the exceptions and handled a specific case (not finding an element).  Also, I put some fields in to remember state for context feedback, and this gave a satisfying output like below.

0    [pool-3-thread-1] INFO  common.driver.LoggingWebDriverEventListener  - WebDriver navigating to:'http://www.google.co.uk'
1453 [pool-3-thread-1] INFO  common.driver.LoggingWebDriverEventListener  - WebDriver changing value in element found by id or name "q" from '' to 'thoughtworks twist'
1478 [pool-3-thread-1] ERROR common.driver.LoggingWebDriverEventListener  - WebDriver error: Element not found By.className: gac_c

Conclusion

I thought the spike worked out well.  There is still a whole load of useful things that could be done here, but out of spike I want to just add them in as we need them.  I’ve handled a couple of things to get a flavour, but there is no point in building a Rolls Royce when may be a push bike will do.  Let me know your thoughts on this, possibly correct my bad coding, or show me how you’ve found some other great way of extending this solution.

Next… How do I get screen shots on Twist HTML reports from a remote IPhone driver???  That should be fun!

4 thoughts on “Logging Selenium 2 Events in Twist”

Leave a Reply