Skip to content

Deadlock when receiving first http request while shutting down context. #4130

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
magJ opened this issue Oct 9, 2015 · 6 comments
Closed
Assignees
Labels
type: bug A general bug
Milestone

Comments

@magJ
Copy link

magJ commented Oct 9, 2015

If we begin to shutdown the spring context while we receive the first HTTP request, spring-boot can deadlock.
It seems that the first HTTP request kicks off some initialization that grabs a lock on the AnnotationConfigEmbeddedWebApplicationContext.

We saw this in a production application, but I managed to replicate it with some success in a demo application:

https://github.com/magJ/spring-boot-deadlock-issue-4130/

It might take a few attempts, but the above application should deadlock eventually.

Spring boot version: 1.2.4-RELEASE
Java Version: 1.8.0_20

I also have a log sample and thread dump of what we saw in out prod application:
https://gist.github.com/magJ/21b075fe38fdace94be8

@magJ magJ changed the title Race condition deadlock with web context Deadlock when receiving first http request while shutting down context. Oct 9, 2015
@wilkinsona wilkinsona self-assigned this Oct 9, 2015
@wilkinsona
Copy link
Member

Thanks very much for the demo application. I've managed to reproduce the problem, both with the versions you were using and with Spring Boot 1.3.0 snapshots on Java 1.8.0 u60.

@wilkinsona
Copy link
Member

Here's a thread dump captured using the latest 1.3.0 snapshot:


2015-10-09 10:19:46
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.60-b23 mixed mode):

"RMI TCP Connection(2)-169.254.202.248" #29 daemon prio=9 os_prio=31 tid=0x00007f9394551000 nid=0x6f07 runnable [0x0000000121a62000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
    at java.net.SocketInputStream.read(SocketInputStream.java:170)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
    at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
    - locked <0x00000007752ca060> (a java.io.BufferedInputStream)
    at java.io.FilterInputStream.read(FilterInputStream.java:83)
    at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:550)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:826)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$256(TCPTransport.java:683)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$$Lambda$10/1432165587.run(Unknown Source)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:682)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - <0x0000000774cbc108> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"JMX server connection timeout 28" #28 daemon prio=9 os_prio=31 tid=0x00007f9394759800 nid=0x5f07 in Object.wait() [0x00000001213c4000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x0000000774ef1180> (a [I)
    at com.sun.jmx.remote.internal.ServerCommunicatorAdmin$Timeout.run(ServerCommunicatorAdmin.java:168)
    - locked <0x0000000774ef1180> (a [I)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - None

"RMI Scheduler(0)" #27 daemon prio=9 os_prio=31 tid=0x00007f939ab39800 nid=0x5a07 waiting on condition [0x00000001212c1000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x0000000774accfa0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - None

"RMI TCP Connection(1)-169.254.202.248" #26 daemon prio=9 os_prio=31 tid=0x00007f939ba35800 nid=0x5707 runnable [0x0000000120ed6000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
    at java.net.SocketInputStream.read(SocketInputStream.java:170)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
    at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
    - locked <0x0000000774ec36e8> (a java.io.BufferedInputStream)
    at java.io.FilterInputStream.read(FilterInputStream.java:83)
    at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:550)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:826)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$256(TCPTransport.java:683)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$$Lambda$10/1432165587.run(Unknown Source)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:682)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - <0x0000000774cbb2f0> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"RMI TCP Accept-0" #25 daemon prio=9 os_prio=31 tid=0x00007f939a50f800 nid=0x3b0b runnable [0x0000000120dd4000]
   java.lang.Thread.State: RUNNABLE
    at java.net.PlainSocketImpl.socketAccept(Native Method)
    at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
    at java.net.ServerSocket.implAccept(ServerSocket.java:545)
    at java.net.ServerSocket.accept(ServerSocket.java:513)
    at sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(LocalRMIServerSocketFactory.java:52)
    at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:400)
    at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:372)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - None

"Attach Listener" #24 daemon prio=9 os_prio=31 tid=0x00007f9399569800 nid=0x3f0b waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"Thread-3" #21 prio=5 os_prio=31 tid=0x00007f9395898000 nid=0x7103 waiting on condition [0x0000000124636000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x0000000773249880> (a java.util.concurrent.FutureTask)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
    at java.util.concurrent.FutureTask.get(FutureTask.java:191)
    at org.apache.catalina.core.ContainerBase.stopInternal(ContainerBase.java:972)
    - locked <0x00000006c07f0d08> (a org.apache.catalina.core.StandardEngine)
    at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:232)
    - locked <0x00000006c07f0d08> (a org.apache.catalina.core.StandardEngine)
    at org.apache.catalina.core.StandardService.stopInternal(StandardService.java:501)
    - locked <0x00000006c07f0d08> (a org.apache.catalina.core.StandardEngine)
    at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:232)
    - locked <0x00000006c07f0bf0> (a org.apache.catalina.core.StandardService)
    at org.apache.catalina.core.StandardServer.stopInternal(StandardServer.java:790)
    at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:232)
    - locked <0x00000006c056cad0> (a org.apache.catalina.core.StandardServer)
    at org.apache.catalina.startup.Tomcat.stop(Tomcat.java:347)
    at org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedServletContainer.stop(TomcatEmbeddedServletContainer.java:229)
    - locked <0x00000006c056cbd0> (a org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedServletContainer)
    at org.springframework.boot.context.embedded.EmbeddedWebApplicationContext.stopAndReleaseEmbeddedServletContainer(EmbeddedWebApplicationContext.java:296)
    - locked <0x00000006c000cc40> (a org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext)
    at org.springframework.boot.context.embedded.EmbeddedWebApplicationContext.doClose(EmbeddedWebApplicationContext.java:150)
    at org.springframework.context.support.AbstractApplicationContext$1.run(AbstractApplicationContext.java:894)

   Locked ownable synchronizers:
    - None

"http-nio-8080-exec-1" #23 daemon prio=5 os_prio=31 tid=0x00007f93939dd800 nid=0x6d03 waiting for monitor entry [0x000000012210c000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at org.springframework.boot.context.embedded.EmbeddedWebApplicationContext.stopAndReleaseEmbeddedServletContainer(EmbeddedWebApplicationContext.java:294)
    - waiting to lock <0x00000006c000cc40> (a org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext)
    at org.springframework.boot.context.embedded.EmbeddedWebApplicationContext.refresh(EmbeddedWebApplicationContext.java:120)
    at org.springframework.web.servlet.FrameworkServlet.configureAndRefreshWebApplicationContext(FrameworkServlet.java:667)
    at org.springframework.web.servlet.FrameworkServlet.initWebApplicationContext(FrameworkServlet.java:539)
    at org.springframework.web.servlet.FrameworkServlet.initServletBean(FrameworkServlet.java:493)
    at org.springframework.web.servlet.HttpServletBean.init(HttpServletBean.java:136)
    at javax.servlet.GenericServlet.init(GenericServlet.java:158)
    at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1231)
    - locked <0x000000078b3b62a0> (a org.apache.catalina.core.StandardWrapper)
    at org.apache.catalina.core.StandardWrapper.allocate(StandardWrapper.java:837)
    at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:694)
    at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:468)
    at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:391)
    at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:318)
    at org.apache.catalina.core.StandardHostValve.custom(StandardHostValve.java:439)
    at org.apache.catalina.core.StandardHostValve.status(StandardHostValve.java:305)
    at org.apache.catalina.core.StandardHostValve.throwable(StandardHostValve.java:399)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:180)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:518)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1091)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:673)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1526)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1482)
    - locked <0x000000077039ddf8> (a org.apache.tomcat.util.net.NioChannel)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - <0x0000000771df4438> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"Thread-4" #22 daemon prio=5 os_prio=31 tid=0x00007f939611a800 nid=0x6b03 runnable [0x0000000124532000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
    at java.net.SocketInputStream.read(SocketInputStream.java:170)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:139)
    at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:155)
    at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:284)
    at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:140)
    at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:57)
    at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:261)
    at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:165)
    at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:167)
    at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:272)
    at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:124)
    at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:271)
    at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:184)
    at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:88)
    at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
    at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:184)
    at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
    at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:107)
    at DeadLockExample.lambda$main$0(DeadLockExample.java:39)
    at DeadLockExample$$Lambda$7/1435304834.run(Unknown Source)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - None

"http-nio-8080-Acceptor-0" #20 daemon prio=5 os_prio=31 tid=0x00007f939b80f000 nid=0x6903 sleeping[0x0000000123f9a000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at org.apache.tomcat.util.net.NioEndpoint$Acceptor.run(NioEndpoint.java:668)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - None

"http-nio-8080-ClientPoller-1" #19 daemon prio=5 os_prio=31 tid=0x00007f939b8c0000 nid=0x6703 sleeping[0x0000000123c08000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:1021)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - None

"http-nio-8080-ClientPoller-0" #18 daemon prio=5 os_prio=31 tid=0x00007f939b9ac800 nid=0x6503 waiting on condition [0x0000000123b05000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:1021)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - None

"NioBlockingSelector.BlockPoller-1" #17 daemon prio=5 os_prio=31 tid=0x00007f9394193000 nid=0x6303 runnable [0x0000000122ea4000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
    at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:198)
    at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:103)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x000000076fdf7788> (a sun.nio.ch.Util$2)
    - locked <0x000000076fdf7700> (a java.util.Collections$UnmodifiableSet)
    - locked <0x000000076fdf7440> (a sun.nio.ch.KQueueSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at org.apache.tomcat.util.net.NioBlockingSelector$BlockPoller.run(NioBlockingSelector.java:342)

   Locked ownable synchronizers:
    - None

"container-0" #16 prio=5 os_prio=31 tid=0x00007f93936fe800 nid=0x6103 waiting on condition [0x0000000122cf8000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at org.apache.catalina.core.StandardServer.await(StandardServer.java:407)
    at org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedServletContainer$1.run(TomcatEmbeddedServletContainer.java:139)

   Locked ownable synchronizers:
    - None

"localhost-startStop-1" #14 daemon prio=5 os_prio=31 tid=0x00007f9399668800 nid=0x5d03 waiting for monitor entry [0x0000000122fb3000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:195)
    - waiting to lock <0x000000078b3b62a0> (a org.apache.catalina.core.StandardWrapper)
    at org.apache.catalina.core.StandardContext.stopInternal(StandardContext.java:5377)
    - locked <0x00000006c07f0fe0> (a org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedContext)
    at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:232)
    - locked <0x00000006c07f0fe0> (a org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedContext)
    at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1424)
    at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1413)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - <0x000000078b420050> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"Tomcat-startStop-1" #13 daemon prio=5 os_prio=31 tid=0x00007f9399668000 nid=0x5c07 waiting on condition [0x000000012200a000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x000000077381f1f8> (a java.util.concurrent.FutureTask)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
    at java.util.concurrent.FutureTask.get(FutureTask.java:191)
    at org.apache.catalina.core.ContainerBase.stopInternal(ContainerBase.java:972)
    - locked <0x00000006c07f0e60> (a org.apache.catalina.core.StandardHost)
    at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:232)
    - locked <0x00000006c07f0e60> (a org.apache.catalina.core.StandardHost)
    at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1424)
    at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1413)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - <0x000000078b422cb0> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"DestroyJavaVM" #12 prio=5 os_prio=31 tid=0x00007f93939bd000 nid=0x1303 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"main" #11 prio=5 os_prio=31 tid=0x00007f9393980800 nid=0x5503 in Object.wait() [0x0000000120b90000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x000000077069b6c8> (a org.springframework.context.support.AbstractApplicationContext$1)
    at java.lang.Thread.join(Thread.java:1245)
    - locked <0x000000077069b6c8> (a org.springframework.context.support.AbstractApplicationContext$1)
    at java.lang.Thread.join(Thread.java:1319)
    at java.lang.ApplicationShutdownHooks.runHooks(ApplicationShutdownHooks.java:106)
    at java.lang.ApplicationShutdownHooks$1.run(ApplicationShutdownHooks.java:46)
    at java.lang.Shutdown.runHooks(Shutdown.java:123)
    at java.lang.Shutdown.sequence(Shutdown.java:167)
    at java.lang.Shutdown.exit(Shutdown.java:212)
    - locked <0x00000006c0385ff8> (a java.lang.Class for java.lang.Shutdown)
    at java.lang.Runtime.exit(Runtime.java:109)
    at java.lang.System.exit(System.java:971)
    at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:57)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - None

"Service Thread" #9 daemon prio=9 os_prio=31 tid=0x00007f9394827800 nid=0x5103 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"C1 CompilerThread3" #8 daemon prio=9 os_prio=31 tid=0x00007f9394001000 nid=0x4f03 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"C2 CompilerThread2" #7 daemon prio=9 os_prio=31 tid=0x00007f9393016800 nid=0x4d03 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"C2 CompilerThread1" #6 daemon prio=9 os_prio=31 tid=0x00007f939300c000 nid=0x4b03 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"C2 CompilerThread0" #5 daemon prio=9 os_prio=31 tid=0x00007f9393863800 nid=0x4903 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"Signal Dispatcher" #4 daemon prio=9 os_prio=31 tid=0x00007f9393836000 nid=0x3a0b runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"Finalizer" #3 daemon prio=8 os_prio=31 tid=0x00007f9394832800 nid=0x3503 in Object.wait() [0x000000011e769000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000006c000b178> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
    - locked <0x00000006c000b178> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

   Locked ownable synchronizers:
    - None

"Reference Handler" #2 daemon prio=10 os_prio=31 tid=0x00007f9394831800 nid=0x3303 in Object.wait() [0x000000011e666000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000006c0009430> (a java.lang.ref.Reference$Lock)
    at java.lang.Object.wait(Object.java:502)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)
    - locked <0x00000006c0009430> (a java.lang.ref.Reference$Lock)

   Locked ownable synchronizers:
    - None

"VM Thread" os_prio=31 tid=0x00007f9393823000 nid=0x3103 runnable 

"GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007f9394013000 nid=0x2103 runnable 

"GC task thread#1 (ParallelGC)" os_prio=31 tid=0x00007f9394013800 nid=0x2303 runnable 

"GC task thread#2 (ParallelGC)" os_prio=31 tid=0x00007f9394014000 nid=0x2503 runnable 

"GC task thread#3 (ParallelGC)" os_prio=31 tid=0x00007f9394800000 nid=0x2703 runnable 

"GC task thread#4 (ParallelGC)" os_prio=31 tid=0x00007f9393802000 nid=0x2903 runnable 

"GC task thread#5 (ParallelGC)" os_prio=31 tid=0x00007f9393803000 nid=0x2b03 runnable 

"GC task thread#6 (ParallelGC)" os_prio=31 tid=0x00007f9393803800 nid=0x2d03 runnable 

"GC task thread#7 (ParallelGC)" os_prio=31 tid=0x00007f9393804000 nid=0x2f03 runnable 

"VM Periodic Task Thread" os_prio=31 tid=0x00007f939301f800 nid=0x5303 waiting on condition 

JNI global references: 292

An HTTP request has been received on thread http-nio-8080-exec-1. This causes the dispatcher
servlet to be initialized. As part of its initialization, it's refreshing the application
context as isActive is returning false. This is wrong. HTTP requests should not be handled
until the application context has been refreshed and is active. Given that things have gone wrong
right from the outset, I'm not sure how much of the following analysis is relevant, but I've done
it now so, for what it's worth, here it is.

Refresh of the application context has thrown a RuntimeException. The exception is caught
and triggers an attempt to stop and release the embedded servlet container. This logic wants to
synchronize on the EmbeddedWebApplicationContext instance (actually an
AnnotationConfiguEmbeddedWebApplicationContext). The monitor's blocked as it's held by Thread-3
which is running a shut down hook.

Thread-3 is running the application context's shutdown hook. As described above, it has
synchronized on the AnnotationConfigEmbeddedWebApplicationContext. It's then calling
ContainerBase.stopInternal which is waiting for a Future to complete. The Future is stopping
one of the container's children. The lock on the AnnotationConfigEmbeddedWebApplicationContext
will not be released until all of the container's children have stopped.

localhost-startStop-1 is handling the stop of the container's child. It has called
StandardContext.stopInternal. This results in it trying to lock a StandardWrapper instance.
This same StandardWrapper instance is currently locked by http-nio-8080-exec-1 resulting in
deadlock.

@wilkinsona
Copy link
Member

Things are going wrong at the outset due to the fact that we stop the embedded container after we've closed the application context:

@Override
protected void doClose() {
    super.doClose();
    stopAndReleaseEmbeddedServletContainer();
}

This means that we can receive a request after the application context has been closed which causes FrameworkServlet to try to refresh it again. Due to the shutdown hook in the scenario above, this means that a refresh and a close attempt race with each other.

The current start up and shut down ordering is:

  1. Refresh context
  2. Start accepting HTTP requests
  3. Close the context
  4. Stop accepting HTTP requests

I would appear to make more sense for the ordering to be:

  1. Refresh context
  2. Start accepting HTTP requests
  3. Stop accepting HTTP requests
  4. Close the context

@wilkinsona wilkinsona added the type: bug A general bug label Oct 9, 2015
@wilkinsona wilkinsona added this to the 1.2.7 milestone Oct 9, 2015
philwebb added a commit that referenced this issue Nov 6, 2015
Update EmbeddedWebApplicationContext so that the servlet container is
shutdown after the context is closed. Unfortunately shutting the
container down before the context has been closed causes exceptions if
the `/shutdown` actuator endpoint is used. It can also cause the Tomcat
classloader to throw IllegalStateExceptions if resources are accessed
during shutdown.

As this commit effectively reverts 0069e41 we need to fix the shutdown
deadlock issue reported in gh-4130 in a different way. The deadlock can
be caused when an incoming HTTP connection occurs whilst the context is
closing. The incoming connection triggers the `FrameworkServlet` to
call `initWebApplicationContext` which in turn calls `refresh`. The
`FrameworkServlet` checks `ApplicationContext.isActive()` before
performing an initialization but prior to this commit we would set
active to `false` before stopping the servlet container. We now override
`onClose` rather than `doClose` in `EmbeddedWebApplicationContext` to
ensure that the active flag is only set to `false` once the servlet
container has been stopped.

See gh-4130
Fixes gh-4396
@philwebb
Copy link
Member

philwebb commented Nov 6, 2015

@magJ Our original fix for this caused some other issues so we've needed to change things. I've tested your original deadlock app and it seems fine but if you get a chance could you please try the latest 1.2.8.BUILD-SNAPSHOT version?

@magJ
Copy link
Author

magJ commented Nov 17, 2015

Sorry for the late reply, but it seems to work fine with the 1.2.8.BUILD-SNAPSHOT version, thanks.

@wilkinsona
Copy link
Member

@magJ Thanks for testing the snapshot.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type: bug A general bug
Projects
None yet
Development

No branches or pull requests

3 participants