Monday, December 24, 2012

Seeing "Info" Messages in a Log Does Not Automatically Imply "Error"

Here's what seems to be a common question among Java language bindings users of the IE driver (tl;dr):

Whenever I use the IE driver, I see an error in my log. The log output is below. How do I stop it?
Started InternetExplorerDriver server (32-bit)
2.28.0.0
Listening on port 48630
Sep 23, 2012 9:12:21 AM org.apache.http.impl.client.DefaultRequestDirector tryExecute
INFO: I/O exception (org.apache.http.NoHttpResponseException) caught when processing request: The target server failed to respond
Sep 23, 2012 9:12:21 AM org.apache.http.impl.client.DefaultRequestDirector tryExecute
INFO: Retrying request


Follow-up questions like, "What happens after you receive this message?" or, "Does the rest of your code run?" usually get a response like, "No, the rest of my code works fine with IE, I just see this error message, and I don't think I should be seeing any errors."

There are two answers to this question, a short one and a long one. The short one is, "Read the log message. It's clearly tagged as 'INFO', as in an informational message, and not indicative of any problem with the code?" I find that this question often comes from users of Eclipse, and that the Eclipse console has colored the message red, and people are so conditioned to see "red == bad" that they react to the format of the message rather than the content. The content of the message is flagged at a level that means, "Hey, nothing is wrong, we're just telling you about it."

If all you care about is how to get around the message, you can stop reading here. The longer answer to the question involves an explanation of why you might receive this message. The explanation requires a little knowledge of the architecture of the WebDriver language bindings in general, and the IE driver in particular. Remember that in the language bindings for most browsers, communication with the browser happens via a "server component", and the language bindings use a JSON-over-HTTP protocol to communicate with that server component. The server component could be an instance of a remote WebDriver server (whether written in Java, or another language); or it could be the Firefox browser extension that the FirefoxDriver installs into an anonymous profile and uses; or it could be an instance of chromedriver.exe; or, and this is the important bit for our purposes here, it could be an instance of IEDriverServer.exe. Each of these server components starts up an HTTP server with which the language bindings can communicate.

Let's think about what happens when you ask the Java language bindings to create a new instance of the InternetExplorerDriver class.


  1. Locate the IEDriverServer.exe, either from the system PATH or from a Java system property
  2. Launch IEDriverServer.exe, including its internal HTTP server
  3. Use the org.apache.http.client.HttpClient class to send HTTP requests to the IEDriverServer's internal HTTP server to launch IE and establish a WebDriver session


Now looking at those steps, can you see the potential flaw in the execution? If you said "race condition," you earn a gold star. The Java method for launching a process will return before the IEDriverServer's HTTP server has had a chance to fully initialize itself and be ready to receive HTTP requests. However, since IEDriverServer.exe is running in a separate process, there's no way for the Java language bindings to know when the HTTP server has fully initialized. The only way to handle the situation is to poll for the HTTP server, repeatedly sending requests until you get a valid response, and that's the message you're seeing in the log. All the bindings are telling you is that the HTTP server hasn't yet been fully initialized, so it's trying the request again, nothing to see here, move along.

The bottom line is that the message is informational, not indicative of an error, or else it would have a different logging level. Remember, the format of a log message is incidental; the important thing is its content.

No comments:

Post a Comment