Jetty 9.x Swallowing Handler Exceptions?

Over the last couple of days I've been pulling out what little hair I had and hoped to save someone else from the same fate. In migrating the WAMulator's embedded Jetty server to version 9.1.5 my builds were suddenly running really slow, tests were failing, and I was seeing numerous lines like this from tests that posted credentials to the WAMulator's sign-in endpoint:

May 14, 2014 6:58:30 AM org.apache.commons.httpclient.HttpMethodDirector executeWithRetry
INFO: Retrying request

No problem. Right? I'd expect some runtime issues. But that line was really peculiar. It was almost as if the sign-in endpoint, implemented as a Jetty Handler, was dropping the connection without sending a response. A lot of digging showed that was definitely the problem when I uncovered some swallowed stack traces like this on the client side of these test meaning in the unit tests themselves not in the WAMulator fielding those http requests:

java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:152)
...

 Furthermore, when I looked at the difference in time from when I made the call to when that stack trace was thrown it was exactly 30 seconds give or take a couple of milliseconds. That looked like a TCP timeout.

So I started up the WAMulator with a debugger and stepped through the sign-in handler line by line until something happened. The short version is that a call to the to addCookie() method of Jetty's Response object was internally calling cookie.isHttpOnly() which was causing a NoMethodFoundException to be thrown.

Now that is definitely a problem that I can and should dig into. But more important to me is why I had to spend so much time tracing through code to figure that out? Why was I not seeing a stack trace along those lines in the console output?

Pay Attention to the Output Stupid

To figure that out I stepped further into Jetty's depths as that exception was caught and re-thrown and finally handled in Jetty's HttpChannel which was indeed logging the exception. Yes, it was being logged. The only problem was that the logger library being used by Jetty was SLF4J and it was logging everything with an instance of NOPLogger which does nothing with such events since it is a "no operation" logger.

I was questioning the quality of a library that doesn't log such errors and forces consumers to dig to these depths to figure out what is wrong. But then I happened to notice some lines in the console output relative to SLF4J now that it was on my mind:

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

Hmmm...that looks like it might be related and I'm looking more like the idiot than the library. So I google it and sure enough, I needed to add something to tell SLF4J where to route its logs since it is just a facade that everyone can leverage to avoid the logging library wars of some years back. And it then requires you to choose to what underlying library of your choice will receive those events. So I added the following dependency in my Maven project to route logging events to the java.util.logging mechanism:

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-jdk14</artifactId>
    <version>1.7.7</version>
</dependency>

And suddenly, viola, my swallowed stack traces were suddenly visible and pointing exactly to where the problem was and where I needed to focus my attention:

May 15, 2014 9:25:16 AM org.eclipse.jetty.util.thread.QueuedThreadPool$3 run
WARNING: 
java.lang.NoSuchMethodError: javax.servlet.http.Cookie.isHttpOnly()Z
at org.eclipse.jetty.server.Response.addCookie(Response.java:239)
at org.lds.sso.appwrap.ui.rest.SelectUserHandler.doHandle(SelectUserHandler.java:193)
at org.lds.sso.appwrap.rest.RestHandlerBase.handle(RestHandlerBase.java:56)
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:109)

...

The Moral of the Story

So if you think Jetty is swallowing exceptions, it probably is. And rightly so. You didn't tell it where to route them. And SLF4J was telling you that when it wrote those lines to the console. If they are there, then you're not getting the whole picture.

Oh, and my underlying problem? Jetty 9 requires Servlet's 3.0. And I was including a dependency on the 2.4 version from my Jetty 6.x days so long ago. Once I changed that, things worked a whole lot better.