SocketException after every response

[Zach Cox]

Hi - just getting started with unfiltered-jetty and wrote this super simple test app (straight outta http://unfiltered.databinder.net):

object Main {
  def main(args: Array[String]) {
    import unfiltered.request._
    import unfiltered.response._
    val echo = unfiltered.filter.Planify {
      case Path(Seg(p :: Nil)) => ResponseString(p)
    }
    unfiltered.jetty.Http.local(8080).filter(echo).run()
  }
}

It definitely works: curl http://localhost:8080/asdf will respond with "asdf". But if I add slf4j and any logging backend (logback-classic, avsl, etc) to the project and use DEBUG level on the root logger, after every HTTP response is returned I see exceptions like this:

[2011/12/10 11:12:59:945 CST] (DEBUG) Server: REQUEST /asdf on org.eclipse.jetty.server.BlockingHttpConnection@213d32a@127.0.0.1:8080<->127.0.0.1:56387
[2011/12/10 11:12:59:947 CST] (DEBUG) ContextHandler: scope null||/asdf @ o.e.j.s.ServletContextHandler{/,null}
[2011/12/10 11:12:59:948 CST] (DEBUG) ContextHandler: context=||/asdf @ o.e.j.s.ServletContextHandler{/,null}
[2011/12/10 11:12:59:950 CST] (DEBUG) ServletHandler: servlet |/asdf|null -> Servlet 2
[2011/12/10 11:12:59:964 CST] (DEBUG) ServletHandler: chain=Filter 1->Servlet 2
[2011/12/10 11:12:59:965 CST] (DEBUG) ServletHandler: call filter Filter 1
[2011/12/10 11:12:59:968 CST] (DEBUG) Server: RESPONSE /asdf  200
[2011/12/10 11:12:59:969 CST] (DEBUG) HttpParser:  java.net.SocketException: Socket is closed
    at java.net.Socket.shutdownInput(Socket.java:1395)
    at org.eclipse.jetty.io.bio.SocketEndPoint.shutdownInput(SocketEndPoint.java:119)
    at org.eclipse.jetty.io.bio.StreamEndPoint.fill(StreamEndPoint.java:142)
    at org.eclipse.jetty.server.bio.SocketConnector$ConnectorEndPoint.fill(SocketConnector.java:213)
    at org.eclipse.jetty.http.HttpParser.fill(HttpParser.java:949)
    at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:274)
    at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:218)
    at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:50)
    at org.eclipse.jetty.server.bio.SocketConnector$ConnectorEndPoint.run(SocketConnector.java:245)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:598)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:533)
    at java.lang.Thread.run(Thread.java:679)

[2011/12/10 11:12:59:972 CST] (DEBUG) HttpParser: state=-14 length=0 len=-3 org.eclipse.jetty.io.EofException
    at org.eclipse.jetty.http.HttpParser.fill(HttpParser.java:954)
    at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:274)
    at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:218)
    at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:50)
    at org.eclipse.jetty.server.bio.SocketConnector$ConnectorEndPoint.run(SocketConnector.java:245)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:598)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:533)
    at java.lang.Thread.run(Thread.java:679)
Caused by: java.net.SocketException: Socket is closed
    at java.net.Socket.shutdownInput(Socket.java:1395)
    at org.eclipse.jetty.io.bio.SocketEndPoint.shutdownInput(SocketEndPoint.java:119)
    at org.eclipse.jetty.io.bio.StreamEndPoint.fill(StreamEndPoint.java:142)
    at org.eclipse.jetty.server.bio.SocketConnector$ConnectorEndPoint.fill(SocketConnector.java:213)
    at org.eclipse.jetty.http.HttpParser.fill(HttpParser.java:949)
    ... 7 more

[2011/12/10 11:12:59:975 CST] (DEBUG) SocketConnector: EOF org.eclipse.jetty.io.EofException
    at org.eclipse.jetty.http.HttpParser.fill(HttpParser.java:954)
    at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:274)
    at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:218)
    at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:50)
    at org.eclipse.jetty.server.bio.SocketConnector$ConnectorEndPoint.run(SocketConnector.java:245)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:598)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:533)
    at java.lang.Thread.run(Thread.java:679)
Caused by: java.net.SocketException: Socket is closed
    at java.net.Socket.shutdownInput(Socket.java:1395)
    at org.eclipse.jetty.io.bio.SocketEndPoint.shutdownInput(SocketEndPoint.java:119)
    at org.eclipse.jetty.io.bio.StreamEndPoint.fill(StreamEndPoint.java:142)
    at org.eclipse.jetty.server.bio.SocketConnector$ConnectorEndPoint.fill(SocketConnector.java:213)
    at org.eclipse.jetty.http.HttpParser.fill(HttpParser.java:949)
    ... 7 more

[2011/12/10 11:12:59:977 CST] (DEBUG) HttpConnection: closed org.eclipse.jetty.server.BlockingHttpConnection@213d32a@127.0.0.1:8080<->127.0.0.1:56387


If I change root logger to INFO then I just never see these stack traces but I assume the exceptions are still thrown.

Is this normal and I should just ignore these? Or am I doing something wrong?

Thanks,
Zach

[Doug Tangren]

I would venture to guess that it's harmless [1]. Unfiltered doesn't leave exception handling up to the application in most cases. It looks like the jetty implementors didn't see this exception as worth anything beyond a debug stmt so I think it should be fine. Otherwise they would have let it bubble up to the application to handle.

[1]: http://osdir.com/ml/java.jetty.support/2002-07/msg00217.html

[Zach Cox]

OK great, thanks for the info. I will filter those stack traces out of
logs & ignore them.

The real app on ec2 is running out of a fat jar, fronted by nginx.
Earlier I was having a problem where nginx would fwd the request to
unfiltered and unfiltered would respond right away, but then nginx
would not return the response. It seemed to repeat the request again
after a couple minutes, those exceptions would get thrown, and then
finally nginx would return the 1st response to the client. But in the
process of trying to distill down the problem I seem to have stopped
nginx from doing this. :/ Will report back if I see this again.

Thanks,
Zach