Bug 57779 - Deadlock if using separate thread to write to ServletOutputStream
Summary: Deadlock if using separate thread to write to ServletOutputStream
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 7
Classification: Unclassified
Component: Connectors (show other bugs)
Version: 7.0.59
Hardware: All All
: P2 major (vote)
Target Milestone: ---
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2015-03-30 12:22 UTC by Bock.Michael
Modified: 2015-04-01 13:01 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Bock.Michael 2015-03-30 12:22:29 UTC
If using a separate (non-container) thread to write to a ServletOutputStream, a deadlock can occur, if an io-error occurs during write. For example, if the client drops the connection.
This is caused by a synchronized operation on the the underlying socket-object.

The servlet handling thread is blocked, while waiting for the end of output from the separate thread, and holds a lock on the socket-object:

"http-bio-25030-exec-10" daemon prio=10 tid=0x0000000001804800 nid=0x3fd0 waiting on condition [0x00007f767aeeb000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000c3b273b8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
 ...
 at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:314)
        - locked <0x00000000c38ef6d8> (a org.apache.tomcat.util.net.SocketWrapper)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:745)


The separate thread trys to write, but an io-error occurs:

"Thread-13" daemon prio=10 tid=0x00007f767c5c8000 nid=0x3fda waiting for monitor entry [0x00007f767a4e2000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at org.apache.tomcat.util.net.JIoEndpoint.processSocketAsync(JIoEndpoint.java:560)
        - waiting to lock <0x00000000c38ef6d8> (a org.apache.tomcat.util.net.SocketWrapper)
        at org.apache.coyote.AbstractProcessor.setErrorState(AbstractProcessor.java:84)
        at org.apache.coyote.http11.AbstractHttp11Processor.action(AbstractHttp11Processor.java:802)
        at org.apache.coyote.Response.action(Response.java:172)
        at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:363)
        at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:331)
        at org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:101)

Now it trys to get a lock on the socket-object and both threads are blocked forever.

In the former tomcat version we used (7.0.53) this was not an issue. I had a look in the source code and saw that the failing code was invented later.
Comment 1 Mark Thomas 2015-03-31 17:24:59 UTC
Full stack traces of both threads please.

As an aside, using the blocking IO connector with the non-blocking API is pointless. Depending on what the stack traces show, this may end up as WONTFIX.
Comment 2 Bock.Michael 2015-04-01 07:17:21 UTC
We are not using the tomcat non blocking io. We simply hand over the ServletOutputStream to another thread. Here are the complete stacktraces:


"http-bio-25030-exec-10" daemon prio=10 tid=0x0000000001804800 nid=0x3fd0 waiting on condition [0x00007f767aeeb000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000c3b273b8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
        at com.qivicon.backend.camera.proxy.ClientInfo.waitForEndOfStream(ClientInfo.java:138)
        at com.qivicon.backend.camera.servlet.StreamServlet.handleRequest(StreamServlet.java:83)
        at sun.reflect.GeneratedMethodAccessor32.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.springframework.web.method.support.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:219)
        at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:132)
        at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:104)
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandleMethod(RequestMappingHandlerAdapter.java:745)
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:686)
        at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:80)
        at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:925)
        at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:856)
        at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:936)
        at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:827)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:620)
        at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:812)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
        at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:118)
        at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:84)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:113)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:113)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:154)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilter(BasicAuthenticationFilter.java:150)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at org.springframework.security.web.authentication.ui.DefaultLoginPageGeneratingFilter.doFilter(DefaultLoginPageGeneratingFilter.java:155)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:199)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:110)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:50)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:87)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:192)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:160)
        at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:343)
        at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:260)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:504)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:421)
        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1074)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)
        at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:314)
        - locked <0x00000000c38ef6d8> (a org.apache.tomcat.util.net.SocketWrapper)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:745)


"Thread-13" daemon prio=10 tid=0x00007f767c5c8000 nid=0x3fda waiting for monitor entry [0x00007f767a4e2000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at org.apache.tomcat.util.net.JIoEndpoint.processSocketAsync(JIoEndpoint.java:560)
        - waiting to lock <0x00000000c38ef6d8> (a org.apache.tomcat.util.net.SocketWrapper)
        at org.apache.coyote.AbstractProcessor.setErrorState(AbstractProcessor.java:84)
        at org.apache.coyote.http11.AbstractHttp11Processor.action(AbstractHttp11Processor.java:802)
        at org.apache.coyote.Response.action(Response.java:172)
        at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:363)
        at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:331)
        at org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:101)
        at com.qivicon.backend.camera.proxy.ClientInfo.write(ClientInfo.java:100)
        at com.qivicon.backend.camera.proxy.WebSocketServerHandler.handleWebSocketFrame(WebSocketServerHandler.java:273)
        at com.qivicon.backend.camera.proxy.WebSocketServerHandler.channelRead0(WebSocketServerHandler.java:99)
        at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:333)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:319)
        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:163)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:333)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:319)
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:787)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:125)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:116)
        at java.lang.Thread.run(Thread.java:745)
Comment 3 Remy Maucherat 2015-04-01 08:10:24 UTC
Ok, but your: parking to wait for  <0x00000000c3b273b8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
does not seem to be related to Tomcat.

The lock on the socket is unavoidable when doing processing, so there won't be any fix in that area.
Comment 4 Bock.Michael 2015-04-01 08:30:00 UTC
We must block the servlet thread to wait for the output from the other thread to be completed. 
In consequence to the changes in 7.0.54 it is generally not possible anymore to use a separate thread to write to the servlet outputstream.
Is this restriction intended?
Comment 5 Remy Maucherat 2015-04-01 09:21:18 UTC
In your trace the deadlock is caused by the lock on <0x00000000c3b273b8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) but it only appears once in your stack, we don't see where it is locked.

I note that 53 works and not 54, but there are no apparently relevant changes. In 55, the error processing was updated to be done in a container thread (the only solution really) and that's where the socket locking is done. This seems legitimate and unavoidable as any async closing attempt is 100% broken.
Comment 6 Bock.Michael 2015-04-01 09:31:07 UTC
We lock the servlet thread with our own lock, which is normally released by the worker thread as soon as the output is processed. 
But this case the worker thread has no chance to release the lock, because it's locked itself in tomcat code.
Comment 7 Mark Thomas 2015-04-01 11:21:14 UTC
Are you using Servlet 3 async processing at all? Or is this all custom async code written on top of - effectively - servlet 2.5?
Comment 8 Bock.Michael 2015-04-01 11:34:27 UTC
This is custom async code written on top of servlet 2.5.

We're now switched the http-connector to Http11NioProtocol. In a first try the lock didn't occur anymore.
Comment 9 Mark Thomas 2015-04-01 13:01:57 UTC
OK. I've stopped Tomcat doing the dispatch to another thread unless Servlet 3+ async is being used. This should enable your code to work with BIO again.

The fix has been made to trunk, 8.0.x (for 8.0.22 onwards) and 7.0.x (for 7.0.62 onwards).

Switching to NIO will avoid the issue since NIO actually does a dispatch to a new thread (which then blocks waiting for the lock) whereas BIo does it in-line.