WebMvcMetricsFilterTests.asyncCallableRequest() hangs intermittently

[wilkinsona]

"main" #1 prio=5 os_prio=0 tid=0x00007f094000a000 nid=0x3440 waiting on condition [0x00007f094746f000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000000f2b38c88> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
	at java.util.concurrent.CyclicBarrier.dowait(CyclicBarrier.java:234)
	at java.util.concurrent.CyclicBarrier.await(CyclicBarrier.java:362)
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilterTests$Controller1.asyncCallable(WebMvcMetricsFilterTests.java:395)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:209)
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:136)
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:102)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:877)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:783)
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:991)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:925)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:974)
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:866)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:635)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:851)
	at org.springframework.test.web.servlet.TestDispatcherServlet.service(TestDispatcherServlet.java:66)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
	at org.springframework.mock.web.MockFilterChain$ServletFilterProxy.doFilter(MockFilterChain.java:166)
	at org.springframework.mock.web.MockFilterChain.doFilter(MockFilterChain.java:133)
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilterTests$RedirectAndNotFoundFilter.doFilterInternal(WebMvcMetricsFilterTests.java:506)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.springframework.mock.web.MockFilterChain.doFilter(MockFilterChain.java:133)
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:158)
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:126)
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:111)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.springframework.mock.web.MockFilterChain.doFilter(MockFilterChain.java:133)
	at org.springframework.test.web.servlet.MockMvc.perform(MockMvc.java:164)
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilterTests.asyncCallableRequest(WebMvcMetricsFilterTests.java:215)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.springframework.test.context.junit4.statements.RunBeforeTestExecutionCallbacks.evaluate(RunBeforeTestExecutionCallbacks.java:73)
	at org.springframework.test.context.junit4.statements.RunAfterTestExecutionCallbacks.evaluate(RunAfterTestExecutionCallbacks.java:83)
	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
	at org.springframework.test.context.junit4.statements.RunBeforeTestMethodCallbacks.evaluate(RunBeforeTestMethodCallbacks.java:75)
	at org.springframework.test.context.junit4.statements.RunAfterTestMethodCallbacks.evaluate(RunAfterTestMethodCallbacks.java:86)
	at org.springframework.test.context.junit4.statements.SpringRepeat.evaluate(SpringRepeat.java:84)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:251)
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:97)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
	at org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61)
	at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:70)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:190)
	at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:369)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:275)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:239)
	at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:160)
	at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:373)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:334)
	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:119)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:407)

[wilkinsona]

I've been unable to recreate this locally, and I'm not sure how things have got into the state indicated by the stack trace. The controller method's being called as a result of this call to perform:

this.mvc.perform(asyncDispatch(result.get())).andExpect(status().isOk());

(result is an AtomicReference for the MvcResult)

At this point, the WebAsyncManager should have a concurrent result and we should be dealing with a ConcurrentResultHandlerMethod. For reasons I don't understand, it appears that that there was no concurrent result so this logic didn't happen:

if (asyncManager.hasConcurrentResult()) {
	Object result = asyncManager.getConcurrentResult();
	mavContainer = (ModelAndViewContainer) asyncManager.getConcurrentResultContext()[0];
	asyncManager.clearConcurrentResult();
	if (logger.isDebugEnabled()) {
		logger.debug("Found concurrent result value [" + result + "]");
	}
	invocableMethod = invocableMethod.wrapConcurrentResult(result);
}

@rstoyanchev Have you seen anything like this before? The test in question is this one.

[rstoyanchev]

@wilkinsona how do you know the concurrent result is set? Normally there is one of two ways. Either you call request().asyncResult(..) which blocks for the result to be come available, or if you have a reference to it, set the async result explicitly.

[wilkinsona]

Thanks for taking a look, @rstoyanchev.

The test calls MockMvcRequestBuilders.asyncDispatch(MvcResult) on line 215. asyncDispatch calls MvcResult.getAsyncResult() and then creates and returns a RequestBuilder. This RequestBuilder is passed into a call to MockMvc.perform(RequestBuilder) which is where there is, apparently, no concurrent result.

[rstoyanchev]

Alas, it looks like a MockMvc issue.

The async value is set on MvcResult through an interceptor, and that releases perform(asyncDispatch(..)) to proceed. However there is a small window of time after that until the concurrentResult is set, see lines 316 vs 325. If you put a break on line 325 to slow down setting the concurrentResult, the main thread proceeds with the asyncDispatch and then hangs upon entering in the controller method.

It looks like at some point we did have a latch to wait for the dispatch, but that was removed in a follow-up fix. Not really sure how it went undetected for so long. Maybe the window is small enough, or perhaps something about this test that makes it a little more likely to fail.

[rstoyanchev]

If you wouldn't mind creating a ticket, I'll pick it up.

[wilkinsona]

Thanks again, @rstoyanchev. I've opened SPR-16648. Closing this issue in favour of that one. We'll pick up the Framework fix in due course.