IllegalStateException for HEAD requests responded with 404

[sbordet]

2016-12-16 18:06:08.449:WARN:oejs.HttpChannel:qtp353842779-131: /foo
java.lang.IllegalArgumentException: setContentLength(0) when already written 318
	at org.eclipse.jetty.server.Response.setContentLength(Response.java:900)
	at javax.servlet.ServletResponseWrapper.setContentLength(ServletResponseWrapper.java:161)
	at javax.servlet.http.NoBodyResponse.setContentLength(HttpServlet.java:830)
	at javax.servlet.http.NoBodyResponse.setContentLength(HttpServlet.java:824)
	at javax.servlet.http.HttpServlet.doHead(HttpServlet.java:289)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:704)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:830)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1634)
	at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:193)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1621)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:541)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:524)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1584)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1228)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:481)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1553)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1130)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:213)
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:118)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
	at org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:335)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
	at org.eclipse.jetty.server.Server.handle(Server.java:564)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:318)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:112)
	at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:261)
	at org.eclipse.jetty.io.ssl.SslConnection$3.succeeded(SslConnection.java:150)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:112)
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:672)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:590)
	at java.lang.Thread.run(Thread.java:745)

[sbordet]

Since the fix for #1045, Jetty checks if the written response body and the content length match, aborting if they don't.

By default, HttpServlet.doHead() wraps the response to wrap the ServletOutputStream to not write the response body, and then tries to set the Content-Length.

However, the default 404 response body generated by Jetty was not written to the wrapped ServletOutputStream, causing HttpServlet.doHead() to think the content was 0, and throwing.

[apprme]

I am still able to reproduce this with jetty 9.4.2.v20170220 (c3e608f is already there, right?):

[INFO] Web overrides =  none
[INFO] jetty-9.4.2.v20170220
[INFO] Scanning elapsed time=1119ms
[INFO] DefaultSessionIdManager workerName=node0
[INFO] No SessionScavenger set, using defaults
[INFO] Scavenging every 660000ms
[INFO] Started o.e.j.m.p.JettyWebAppContext@5f5c187d{/,file:///Users/appr/dev/orenlinux/simplefilehosting/server/target/server-1.0-SNAPSHOT/,AVAILABLE}{/Users/appr/dev/orenlinux/simplefilehosting/server/target/server-1.0-SNAPSHOT}
[INFO] Started ServerConnector@5c65fa69{HTTP/1.1,[http/1.1]}{0.0.0.0:8080}
[INFO] Started @7989ms
[INFO] Started Jetty Server
[INFO] Using Non-Native Java sun.nio.fs.PollingWatchService
[WARNING] Quiet Time is too low for non-native WatchService [sun.nio.fs.PollingWatchService]: 1000 < 5000 ms (defaulting to 5000 ms)
[WARNING] /test
java.lang.IllegalArgumentException: setContentLength(0) when already written 324
        at org.eclipse.jetty.server.Response.setContentLength(Response.java:912)
        at javax.servlet.ServletResponseWrapper.setContentLength(ServletResponseWrapper.java:161)
        at javax.servlet.http.NoBodyResponse.setContentLength(HttpServlet.java:830)
        at javax.servlet.http.NoBodyResponse.setContentLength(HttpServlet.java:824)
        at javax.servlet.http.HttpServlet.doHead(HttpServlet.java:289)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:704)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:833)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1634)
        at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:206)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1621)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:541)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1592)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1239)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:481)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1561)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1141)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
        at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:213)
        at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:118)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
        at org.eclipse.jetty.server.Server.handle(Server.java:564)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:320)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:110)
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:672)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:590)
        at java.lang.Thread.run(Thread.java:745)

@WebServlet(urlPatterns = {"/test"})
public class AliasServlet extends HttpServlet {

  @Override
  protected void doGet(HttpServletRequest req, HttpServletResponse resp) throws ServletException, IOException {
    resp.sendError(HttpServletResponse.SC_BAD_REQUEST);
  }
}

$ curl 'http://localhost:8080/test' --head

[sbordet]

Not all code paths were covered, so the issue is still present for requests with the Accept header and a non-404 response.

[thomashunziker]

I have the same issue with the version 9.4.4.v20170414. When I understand this correctly this should not happen anymore with this version.

I cannot reproduce it by myself. However I see it in the production environment. Stacktrace:

java.lang.IllegalArgumentException: setContentLength(0) when already written 1232
	at org.eclipse.jetty.server.Response.setContentLength(Response.java:1007)
	at javax.servlet.ServletResponseWrapper.setContentLength(ServletResponseWrapper.java:161)
	at javax.servlet.http.NoBodyResponse.setContentLength(HttpServlet.java:830)
	at javax.servlet.http.NoBodyResponse.setContentLength(HttpServlet.java:824)
	at javax.servlet.http.HttpServlet.doHead(HttpServlet.java:289)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:704)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:841)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1634)
	at io.company.framework.core.api.util.main.filter.SessionFilter.doFilter(SessionFilter.java:36)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1621)
	at io.company.framework.core.api.util.main.filter.LanguageHandlerFilter.doFilter(LanguageHandlerFilter.java:46)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1621)
	at io.company.framework.core.api.util.main.filter.ErrorHandlerFilter.doFilter(ErrorHandlerFilter.java:56)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1621)
	at io.company.framework.core.api.util.main.filter.CloseForwardedConnectionsFilter.doFilter(CloseForwardedConnectionsFilter.java:77)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1621)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:541)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:481)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:61)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
	at io.company.framework.core.api.util.main.MultipartConfigInjectionHandler.handle(MultipartConfigInjectionHandler.java:79)
	at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:454)
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
	at org.eclipse.jetty.server.Server.handle(Server.java:564)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:317)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:110)
	at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:278)
	at org.eclipse.jetty.io.ssl.SslConnection$3.succeeded(SslConnection.java:148)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:110)
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)
	at org.eclipse.jetty.util.thread.Invocable.invokePreferred(Invocable.java:128)
	at org.eclipse.jetty.util.thread.Invocable$InvocableExecutor.invoke(Invocable.java:222)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:294)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:199)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:672)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:590)
	at java.lang.Thread.run(Thread.java:745)

The headers of the request:

CF-IPCountry: US
CF-RAY: 3641b8327d8e7924-LAX
Connection: keep-alive
X-Forwarded-Proto: https
User-Agent: Mozilla/5.0 (compatible; Uptimebot/1.0; +http://www.uptime.com/uptimebot)
Referer: http://uptime.com/
X-Forwarded-For: 199.58.164.122
Host: xxxxxxxxxx.com
CF-Visitor: { \"scheme\":\"https\"}
Accept-Encoding: gzip
CF-Connecting-IP: 199.58.164.122

Have you any idea why this is happening?

[joakime]

@thomashunziker you said you sent a GET request, but the stacktrace shows a HEAD being processed.

javax.servlet.http.HttpServlet.doHead

If this is easy to reproduce, i would suggest temporarily disabling your filters and trying again.
If you can still reproduce, then the issue is likely in Jetty.
If you cannot reproduce after removing the filters, then something about your filters is changing the behavior. (likely something is changing the request.getMethod() call to return HEAD)

[thomashunziker]

@joakime Thank you very much for your help. After finally I was able to reproduce the error locally I could debug / trace it down.

The solution was to use the latest version 9.4.6. Means one of the changes made in between version 9.4.4 and 9.4.6 has fixed the issue. Sorry for bothering you.

[joakime]

@thomashunziker thanks for the feedback. closing this issue.