Trace Writes inside Selenium Tests

The Selenium web browser automation framework can be useful for integration testing of a web application, since it drives actual web browsers interacting with your application like a real user would—but a lot faster. Because of its reaction speed, it can sometimes uncover race conditions in modern, complex applications that may be difficult to reproduce in the real world.

Normally, when running into a reproducible test case that’s exhibiting unexpected behavior, I’ll want to get into it with some sort of debugging tool. If I’m driving the application myself and need it to run uninterrupted to reproduce the error, I can use the old faithful console.log statement to print trace writes to the browser’s JavaScript console and inspect the sequence of events and/or potentially useful data after-the-fact. However, if Selenium-driven integration tests are the only place I can reliably reproduce my issue, I have a problem with this strategy: I can’t get into the JavaScript console—it aborts the session and I lose those logged messages.

My solution to this problem is to collect trace writes inside a globally-available JavaScript string, acting as a log buffer, with a special trace function:

function TRACE(message) {
    if (!window._TRACE) {
        window._TRACE = '';
    }
    
    window._TRACE = window._TRACE + Date.now() + ': ' + message + '\r\n';
    
    console.log('TRACE: ' + message);
}

I make this function globally available throughout my codebase, then use it wherever I need to emit trace writes. The console.log call means I can readily see the trace writes in an interactive session, but when I’m running this code under Selenium-driven tests, I need one more thing to extract the results of the tracing at the end of the test. I’ll use Selenium’s ability to run arbitrary JavaScript (shown here in Java) to extract the values of my trace buffer and print them:

JavascriptExecutor js = (JavascriptExecutor)webDriver;
System.err.println(js.executeScript("return window.TRACE;"));

With that I get, in my test output, a nicely-formatted, timestamped print-out of all the trace writes in my code. It’s a pretty straightforward process, but it’s already proved valuable for me when tracking down race conditions inside pages with a lot of things going on. Hopefully, it can help you out with your tricky problems too.