Async DeferredResult OpenSessionInViewFilter [SPR-10874]

[spring-projects-issues]

Stig Runar Vangen opened SPR-10874 and commented

In a controller I return a DeferredResult in order to set up an async request. From an another thread I set the result of DeferredResult, and thus return the result back to the user.

The problem lies in that I also use a OpenSessionInViewFilter for Hibernate session management. This filter gives an error now and then indicating that a session is not bound to the current thread.

Stack trace is as follows:

29.aug.2013 11:15:57 [http-bio-8080-exec-1] ERROR org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/].[appServlet] - Servlet.service() for servlet appServlet threw exception java.lang.IllegalStateException: No value for key [org.hibernate.internal.SessionFactoryImpl@28af7fd7] bound to thread [http-bio-8080-exec-1]
	at org.springframework.transaction.support.TransactionSynchronizationManager.unbindResource(TransactionSynchronizationManager.java:209)
	at org.springframework.orm.hibernate4.support.OpenSessionInViewFilter.doFilterInternal(OpenSessionInViewFilter.java:157)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
	at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:749)
	at org.apache.catalina.core.ApplicationDispatcher.doDispatch(ApplicationDispatcher.java:660)
	at org.apache.catalina.core.ApplicationDispatcher.dispatch(ApplicationDispatcher.java:626)
	at org.apache.catalina.core.AsyncContextImpl$1.run(AsyncContextImpl.java:225)
	at org.apache.catalina.core.AsyncContextImpl.doInternalDispatch(AsyncContextImpl.java:367)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:217)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99)
	at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:953)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
	at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:299)
	at org.apache.coyote.http11.AbstractHttp11Processor.asyncDispatch(AbstractHttp11Processor.java:1587)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:583)
	at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:312)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
	at java.lang.Thread.run(Thread.java:722)

29.aug.2013 11:15:57 [http-bio-8080-exec-1] ERROR org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/].[appServlet] - Servlet.service() for servlet [appServlet] in context with path [] threw exception [java.lang.RuntimeException: java.lang.IllegalStateException: No value for key [org.hibernate.internal.SessionFactoryImpl@28af7fd7] bound to thread [http-bio-8080-exec-1]] with root cause java.lang.IllegalStateException: No value for key [org.hibernate.internal.SessionFactoryImpl@28af7fd7] bound to thread [http-bio-8080-exec-1]
	at org.springframework.transaction.support.TransactionSynchronizationManager.unbindResource(TransactionSynchronizationManager.java:209)
	at org.springframework.orm.hibernate4.support.OpenSessionInViewFilter.doFilterInternal(OpenSessionInViewFilter.java:157)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
	at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:749)
	at org.apache.catalina.core.ApplicationDispatcher.doDispatch(ApplicationDispatcher.java:660)
	at org.apache.catalina.core.ApplicationDispatcher.dispatch(ApplicationDispatcher.java:626)
	at org.apache.catalina.core.AsyncContextImpl$1.run(AsyncContextImpl.java:225)
	at org.apache.catalina.core.AsyncContextImpl.doInternalDispatch(AsyncContextImpl.java:367)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:217)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99)
	at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:953)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
	at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:299)
	at org.apache.coyote.http11.AbstractHttp11Processor.asyncDispatch(AbstractHttp11Processor.java:1587)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:583)
	at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:312)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
	at java.lang.Thread.run(Thread.java:722)

---

Affects: 3.2.4

Attachments:

• transaction-trace.txt (22.53 kB)
• wisweb2.log (5.24 MB)
• wisweb2.log (1.48 MB)

Referenced from: commits f9081be, 5d8fac8

[spring-projects-issues]

Rossen Stoyanchev commented

Can you attach a log file from the request execution with "org.springframework" set to DEBUG level?

[spring-projects-issues]

Stig Runar Vangen commented

This is the log file as requested.

I've tried some more with this setup, and it seems like this error occurs if the async request is cancelled by the user either by closing the tab or pressing F5/refresh.

Another detail worth mentioning, is that the database pool gets drained after a while, as the connections are never returned to the pool for the failed requests.

[spring-projects-issues]

Rossen Stoyanchev commented

It doesn't seem like you're using Spring MVC annotated controllers (i.e. returning DeferredResult from a controller method), or at least I don't see any messages from the DispatcherServlet. Can you elaborate how you're using DeferredResult? A code snippet maybe that shows the bits that relate to async processing.

[spring-projects-issues]

Stig Runar Vangen commented

We are using a custom version of the dispatcher. Because this dispatcher is placed in a different package, it did not show up in the log. I've added debug logging for that package as well in this version of the log.

This is the controller method that sets up the async request:

@ResponseBody
@RequestMapping(value = "/getAsync", produces = "application/json")
public final DeferredResult<ServerMessage> getAsync() {
    return this.notificationManager.createDeferred();
}

[spring-projects-issues]

Rossen Stoyanchev commented

I've tried some more with this setup, and it seems like this error occurs if the async request is cancelled by the user either by closing the tab or pressing F5/refresh.

Can you explain a little more how you reproduce it? In the log I see many calls to ServerMessageController.getAsync(). Do you need to run it under a load to get it to fail or do you have a set of steps to make it fail?

[spring-projects-issues]

Stig Runar Vangen commented

This error is easily reproduced on my development computer, so not load is required.

For debugging purposes I have two requests that I access using two web browser windows. ServerMessageController.getAsync() which waits for a message on the message queue, and InternalMessageController.create() which creates debug messages on the message queue.

First I fire up a getAsync request, which waits. I then call the create request, and see that data gets shown in the first request. I then refreshes the getAsync page, and see that waiting starts again. I refresh this page a few times, and therefore cancel some of the requests to the server. After sending a few debug messages using the create request I can see that the cancelled wait-requests give error messages.

[spring-projects-issues]

Rossen Stoyanchev commented

I haven't been able to reproduce the exact issue yet. However, there is definitely something that needs to be addressed in the mean time that could explain the session leak. OpenSessionInViewFilter needs to have some handling added after the async request times out. Is it possible that async requests are timing out? Unless configured otherwise by default the timeout on Tomcat is 10 seconds. One easy way to detect this for sure is to add an onTimeout(Runnable) callback to the DeferredResult and log a debug message. Also keep in mind you can provide a default result to use to the DeferredResult constructor in case of timeout.

As for the IllegalStateException it is strange the TransactionSynchronizationManager is not able to locate the session in the thread local map. Something must be clearing it and it's not obvious from the output what. I'll have to ask you for logging information once more this time with logging for org.springframework.transaction.support.TransactionSynchronizationManager set to TRACE. This will show every time a session is bound and unbound from the current thread and hopefully help to track this down.

[spring-projects-issues]

Rossen Stoyanchev commented

I'm moving this to 4.0 RC2 since I haven't yet reproduced the IllegalStateException. However, I have committed a fix for the timeout handling if you want to go ahead and give it a try. You can use 3.2.5.BUILD-SNAPSHOT (http://repo.springsource.org/snapshot) or it should also be easy to patch your environment temporarily.

[spring-projects-issues]

Stig Runar Vangen commented

I've tried to make a simple example that shows this problem. With most related systems in place, the error does not show up. Looking through the flow of the OpenSessionInViewFilter implementation, I'm starting to think the whole problem is related to our use of custom scopes. It might be that a different scope is used in the initialization of this filter than at the end. The filter will therefore not find the attached session factory.

The plan is to revisit the scope implementation, as it also give some other weird bugs. Until then I cannot confirm if that is the problem, but I highly suspect it.

[spring-projects-issues]

Rossen Stoyanchev commented

Are you using the latest snapshot? I'm curious if the issue with leaking sessions is resolved.

[spring-projects-issues]

Rossen Stoyanchev commented

Regarding custom scopes, the OpenSessionInViewFilter uses TransactionSynchronizationManager and ultimately ThreadLocal storage. It's not obvious immediately how it could be affected by the use of custom scopes. I would try TRACE logging to find out if anything unbinds the session earlier.

[spring-projects-issues]

Stig Runar Vangen commented

Attached are the logs I got when I updated to 3.2.5 SNAPSHOT and sat org.springframework.transaction logging to TRACE. Seems like the session was unbound, but was requested from an another thread.

[spring-projects-issues]

Rossen Stoyanchev commented

Attached are the logs I got when I updated to 3.2.5 SNAPSHOT and sat org.springframework.transaction logging to TRACE. Seems like the session was unbound, but was requested from an another thread.

Actually the session appears to be always bound and unbound in pairs, which is good. The two exceptions logged are in threads 1 and 3 for both of which the preceding messages are "Bound value" followed by "Retrieved value" but there is no "Removed value". So I don't think the issue is that session is unbound from somewhere.

The issue that I see is the key. TransactionSynchronizationManager uses the SessionFactory as the key. The OpenSessionInViewFilter looks up the SessionFactory by name and type from the WebApplicationContext so I'd expect the key to remain the same always. Indeed it is [org.hibernate.internal.SessionFactoryImpl@206c2545] in most cases. However, both exceptions show a different key, one that ends on @5beb3e57, and one that thread 10 happens to use around the exact same time. The only conclusion I can make at this point is that somehow the WebApplicationContext is re-initialized and set on the ServletContext. No other way I can explain why a different SessionFactory instance would be returned. What's even more puzzling is this appears to happen in the middle of a request (albeit an async request).

I'm hoping this rings some bell as to what might be causing this in your environment. Other than that what would have been helpful is to see the TRACE output interleaved with all other log statements. Did you extract these log lines only or set the logging to exclude all else? In the very least add org.springframework.web at DEBUG level.

[spring-projects-issues]

Stig Runar Vangen commented

In our application we use a custom scope that could at any point during the request be changed. This mid-request change of scope caused some other issues as well, and has therefore been changed so that the scope is set only once during each request. This might be the reason why it seems that the WebApplicationContext is re-initialized. When the scope changes, the session factory will not be known to the application within that scope, as the OpenSessionInViewFilter has initialized the session factory within an another scope, and data retrieval fails.

The good news is that now that the situation regarding the custom scope has been fixed in our application, this error do no longer appear. I therefore believe that this error was caused by problems within our application, and not within the Spring library.

[spring-projects-issues]

Juergen Hoeller commented

Alright, let's consider this as fixed as of 4.0 RC1 and 3.2.5 then, which is when the fix for the timeout issue got committed.

Juergen