Jetty, DefaultServlet, BlockingCallback and TimeoutException issue

Question

I am running an online application powered by Jetty 9.1.0.RC1 (standalone distribution).

My log file gets filled up by the following issues occuring randomly when serving static content (.js, .css, .png files etc.):

2013-11-25 07:43:37.351:WARN:oejs.ServletHandler:qtp1207851091-422: /scripts/shared/channel/channel.public.js
java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 75000/75000 ms
    at org.eclipse.jetty.util.BlockingCallback.block(BlockingCallback.java:101)
    at org.eclipse.jetty.server.HttpOutput.sendContent(HttpOutput.java:490)
    at org.eclipse.jetty.servlet.DefaultServlet.sendData(DefaultServlet.java:893)
    at org.eclipse.jetty.servlet.DefaultServlet.doGet(DefaultServlet.java:499)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:696)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1566)
    at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:164)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1537)
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:524)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
    at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:568)
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:221)
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1110)
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:453)
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:183)
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1044)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
    at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:200)
    at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:109)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
    at org.eclipse.jetty.server.Server.handle(Server.java:442)
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:279)
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:213)
    at org.eclipse.jetty.io.AbstractConnection$1.run(AbstractConnection.java:505)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:601)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:532)
    at java.lang.Thread.run(Thread.java:722)
Caused by: 
java.util.concurrent.TimeoutException: Idle timeout expired: 75000/75000 ms
    at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:153)
    at org.eclipse.jetty.io.IdleTimeout$1.run(IdleTimeout.java:50)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
    at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
    at java.util.concurrent.FutureTask.run(FutureTask.java:166)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:722)

The same applies for resources such as:

2013-11-26 15:09:01.219:WARN:oejs.ServletHandler:qtp1207851091-629: /Resources/Audio/IncomingMessage.wav

2013-11-25 03:02:44.904:WARN:oejs.ServletHandler:qtp1207851091-408: /Resources/Website/Users/f3c68328-d739-4680-8144-a0db598dff6b/1384157586003.png

I'm using servlet 3.0. There are two DefaultServlet 's instances, one from webdefault.xml, and another one from web.xml to serve user images (which are not bundled with .war file).

The config for the former DefaultServlet is not modified, the latter is as follows:

<servlet>
    <servlet-name>DefaultImagesServlet</servlet-name>
    <servlet-class>org.eclipse.jetty.servlet.DefaultServlet</servlet-class>
    <init-param>
        <param-name>resourceBase</param-name>
        <param-value>/echat/static/</param-value>
    </init-param>
</servlet>
<servlet-mapping>
    <servlet-name>DefaultImagesServlet</servlet-name>
    <url-pattern>/Resources/*</url-pattern>
</servlet-mapping>

I've spent last 3 days trying to figure this thing out, still am stuck. I am not using Continuation anywhere explicitly in the application.

The issue only occurs few days after jetty has been (re)started.

Any clue where to look for the answer? It seems like I've exhausted all the possible options.

Kind Regards,

Michael Zyskowski

score 0 · Answer 1 · answered Nov 27 '13 at 16:37

The second DefaultServlet should have 1 more init-param ...

<servlet>
    <servlet-name>DefaultImagesServlet</servlet-name>
    <servlet-class>org.eclipse.jetty.servlet.DefaultServlet</servlet-class>
    <init-param>
        <param-name>resourceBase</param-name>
        <param-value>/echat/static/</param-value>
    </init-param>
    <init-param>
        <param-name>pathInfoOnly</param-name> <!-- this should be set -->
        <param-value>true</param-value>
    </init-param>
</servlet>
<servlet-mapping>
    <servlet-name>DefaultImagesServlet</servlet-name>
    <url-pattern>/Resources/*</url-pattern>
</servlet-mapping>

The Idle Timeout you are seeing is from an active (unclosed) connection where nothing is happening for a period of time.

Also, you should capture the HTTP traffic, there is likely something wrong going on with the requests being made vs what is being returned. This is particularly important to know if the request/response headers are HTTP/1.0 and keep-alive state, or HTTP/1.1 and bad Connection state.

Another thing to do, is enable the following logging at debug level when testing (if using the fallback StdErrLog logging in Jetty itself).

System.setProperty("org.eclipse.jetty.servlet.LEVEL","DEBUG");

That will show the Resource being requested, vs what is attempting to be found on disk.

Example: Assuming the original configuration for DefaultImagesServlet you have in your question.

The request for /Resources/scripts/main.js would look for a file on your filesystem as /echat/static/Resources/scripts/main.js. This behavior is consistent with the special requirements for the servlet spec "default" (named) servlet behavior mapped at the path spec of "/".

With the pathInfoOnly setting, the request for /Resources/scripts/main.js would pull from the filesystem at /echat/static/scripts/main.js, which is more consistent with how normal Servlets behave.

Jetty, DefaultServlet, BlockingCallback and TimeoutException issue

1 Answers1