Bug 62175

Summary: Infinite recursive session PersistentManager.swapIn loop with OOM
Product: Tomcat 9 Reporter: Holger Sunke <holger.sunke>
Component: CatalinaAssignee: Tomcat Developers Mailing List <dev>
Status: RESOLVED FIXED    
Severity: normal    
Priority: P2    
Version: 9.0.6   
Target Milestone: -----   
Hardware: PC   
OS: All   
Attachments: Test case that shows infinite recursion on session loading
Refactor part one to make fix more readable
Refactor part two to make fix more readable
Refactoring part three to make fix more readable
Store currently loaded session in thread local storage to load it only once
Store currently loaded session in thread local storage to load it only once

Description Holger Sunke 2018-03-13 10:59:48 UTC
Environment:
Windows 8 NTFS
Oracle JDK 1.8.0_152
Apache Tomcat 9.0.6
Apache OpenWebBeans 2.0.4 (OWB)
Session ID ABCDE in filesystem storage and containing an expired session.

TL;DR: Expired session is deserialized over and over again because OWB calls Request.getSession(false) in sessionDestroyed and ContainerBackgroundProcessor is unable to delete the session file while it is deserialized.


While Tomcat is starting up, I direct the Browser to request my application with session ABCDE which had been swapped out but is already expired.
Tomcat calls 
StandardSession.isValid() 
-> StandardSession.expire()
-> each registered HttpSessionListener.destroy()

Now OWB having a HttpSessionListener registered is calling RequestFacade.getSession(false) which expands to
-> PersistentManager.findSession()
-> PersistentManager.swapIn()
-> StandardSession.isValid()
... repeat until OutOfMemory

An important side condition is that FileStore.remove() fails for unknown reason. File.delete just returns false which is not very expressive. Maybe the session file is beeing read / locked accidentally the same time while the ContainerBackgroundProcessor tries to delete it. This could be caused by the session beeing read over and over again by that recursive loop where the most expansive operation is deserialization of the session, giving close to zero time for a successful delete.

[This is one reason why I better like Linux: deleting a file while it is read simply deletes the file.]

BTW: When the HTTP-Thread is blocked by a breakpoint, ContainerBackgroundProcessor succeeds in deleting the file and stops the recursion.


Here are the stacktraces of HTTP thread and ContainerBackgroundProcessor:

"http-nio-8080-exec-2" #66 daemon prio=5 os_prio=0 tid=0x0000000021e9b000 nid=0xf94 at breakpoint[0x000000002c40a000]
   java.lang.Thread.State: RUNNABLE
        at my.web.common.application.listener.ApplicationListener.sessionDestroyed(ApplicationListener.java:112)
        at org.apache.catalina.session.StandardSession.expire(StandardSession.java:801)
        - locked <0x00000000d709d800> (a org.apache.catalina.session.StandardSession)
        at org.apache.catalina.session.StandardSession.isValid(StandardSession.java:659)
        at org.apache.catalina.session.PersistentManagerBase.swapIn(PersistentManagerBase.java:736)
        - locked <0x00000000fa5be668> (a java.lang.Object)
        at org.apache.catalina.session.PersistentManagerBase.findSession(PersistentManagerBase.java:488)
        at org.apache.catalina.connector.Request.doGetSession(Request.java:2909)
        at org.apache.catalina.connector.Request.getSession(Request.java:2374)
        at org.apache.catalina.connector.RequestFacade.getSession(RequestFacade.java:908)
        at org.apache.webbeans.web.context.WebContextsService.destroySessionContext(WebContextsService.java:553)
        at org.apache.webbeans.web.context.WebContextsService.endContext(WebContextsService.java:228)
        at org.apache.webbeans.servlet.WebBeansConfigurationListener.sessionDestroyed(WebBeansConfigurationListener.java:197)
        at org.apache.catalina.session.StandardSession.expire(StandardSession.java:801)
        - locked <0x00000000d61c8d48> (a org.apache.catalina.session.StandardSession)
        at org.apache.catalina.session.StandardSession.isValid(StandardSession.java:659)
        at org.apache.catalina.session.PersistentManagerBase.swapIn(PersistentManagerBase.java:736)
        - locked <0x00000000fa5be668> (a java.lang.Object)
        at org.apache.catalina.session.PersistentManagerBase.findSession(PersistentManagerBase.java:488)
        at org.apache.catalina.connector.Request.doGetSession(Request.java:2909)
        at org.apache.catalina.connector.Request.getSession(Request.java:2374)
        at org.apache.catalina.connector.RequestFacade.getSession(RequestFacade.java:908)
        at org.apache.webbeans.web.context.WebContextsService.destroySessionContext(WebContextsService.java:553)
        at org.apache.webbeans.web.context.WebContextsService.endContext(WebContextsService.java:228)
        at org.apache.webbeans.servlet.WebBeansConfigurationListener.sessionDestroyed(WebBeansConfigurationListener.java:197)
        at org.apache.catalina.session.StandardSession.expire(StandardSession.java:801)
        - locked <0x00000000fbb10008> (a org.apache.catalina.session.StandardSession)
        at org.apache.catalina.session.StandardSession.isValid(StandardSession.java:659)
        at org.apache.catalina.session.PersistentManagerBase.swapIn(PersistentManagerBase.java:736)
        - locked <0x00000000fa5be668> (a java.lang.Object)
        at org.apache.catalina.session.PersistentManagerBase.findSession(PersistentManagerBase.java:488)
        at org.apache.catalina.connector.Request.doGetSession(Request.java:2909)
        at org.apache.catalina.connector.Request.getSession(Request.java:2374)
        at org.apache.catalina.connector.RequestFacade.getSession(RequestFacade.java:908)
        at org.apache.webbeans.web.context.WebContextsService.destroySessionContext(WebContextsService.java:553)
        at org.apache.webbeans.web.context.WebContextsService.endContext(WebContextsService.java:228)
        at org.apache.webbeans.servlet.WebBeansConfigurationListener.sessionDestroyed(WebBeansConfigurationListener.java:197)
        at org.apache.catalina.session.StandardSession.expire(StandardSession.java:801)
        - locked <0x00000000fbb100d8> (a org.apache.catalina.session.StandardSession)
        at org.apache.catalina.session.StandardSession.isValid(StandardSession.java:659)
        at org.apache.catalina.session.PersistentManagerBase.swapIn(PersistentManagerBase.java:736)
        - locked <0x00000000fa5be668> (a java.lang.Object)
        at org.apache.catalina.session.PersistentManagerBase.findSession(PersistentManagerBase.java:488)
        at org.apache.catalina.connector.Request.doGetSession(Request.java:2909)
        at org.apache.catalina.connector.Request.getSession(Request.java:2374)
        at org.apache.catalina.connector.RequestFacade.getSession(RequestFacade.java:908)
        at org.apache.webbeans.web.context.WebContextsService.destroySessionContext(WebContextsService.java:553)
        at org.apache.webbeans.web.context.WebContextsService.endContext(WebContextsService.java:228)
        at org.apache.webbeans.servlet.WebBeansConfigurationListener.sessionDestroyed(WebBeansConfigurationListener.java:197)
        at org.apache.catalina.session.StandardSession.expire(StandardSession.java:801)
        - locked <0x00000000fbb10150> (a org.apache.catalina.session.StandardSession)
        at org.apache.catalina.session.StandardSession.isValid(StandardSession.java:659)
        at org.apache.catalina.session.PersistentManagerBase.swapIn(PersistentManagerBase.java:736)
        - locked <0x00000000fa5be668> (a java.lang.Object)
        at org.apache.catalina.session.PersistentManagerBase.findSession(PersistentManagerBase.java:488)
        at org.apache.catalina.connector.Request.doGetSession(Request.java:2909)
        at org.apache.catalina.connector.Request.getSession(Request.java:2374)
        at org.apache.catalina.connector.RequestFacade.getSession(RequestFacade.java:908)
        at org.apache.webbeans.web.context.WebContextsService.destroySessionContext(WebContextsService.java:553)
        at org.apache.webbeans.web.context.WebContextsService.endContext(WebContextsService.java:228)
        at org.apache.webbeans.servlet.WebBeansConfigurationListener.sessionDestroyed(WebBeansConfigurationListener.java:197)
        at org.apache.catalina.session.StandardSession.expire(StandardSession.java:801)
        - locked <0x00000000fbb101c8> (a org.apache.catalina.session.StandardSession)
        at org.apache.catalina.session.StandardSession.isValid(StandardSession.java:659)
        at org.apache.catalina.session.PersistentManagerBase.swapIn(PersistentManagerBase.java:736)
        - locked <0x00000000fa5be668> (a java.lang.Object)
        at org.apache.catalina.session.PersistentManagerBase.findSession(PersistentManagerBase.java:488)
        at org.apache.catalina.connector.Request.doGetSession(Request.java:2909)
        at org.apache.catalina.connector.Request.getSession(Request.java:2374)
        at org.apache.catalina.connector.RequestFacade.getSession(RequestFacade.java:908)
        at org.apache.webbeans.web.context.WebContextsService.destroySessionContext(WebContextsService.java:553)
        at org.apache.webbeans.web.context.WebContextsService.endContext(WebContextsService.java:228)
        at org.apache.webbeans.servlet.WebBeansConfigurationListener.sessionDestroyed(WebBeansConfigurationListener.java:197)
        at org.apache.catalina.session.StandardSession.expire(StandardSession.java:801)
        - locked <0x00000000fbb10240> (a org.apache.catalina.session.StandardSession)
        at org.apache.catalina.session.StandardSession.isValid(StandardSession.java:659)
        at org.apache.catalina.session.PersistentManagerBase.swapIn(PersistentManagerBase.java:736)
        - locked <0x00000000fa5be668> (a java.lang.Object)
        at org.apache.catalina.session.PersistentManagerBase.findSession(PersistentManagerBase.java:488)
        at org.apache.catalina.connector.Request.doGetSession(Request.java:2909)
        at org.apache.catalina.connector.Request.getSession(Request.java:2374)
        at org.apache.catalina.connector.RequestFacade.getSession(RequestFacade.java:908)
        at org.apache.webbeans.web.context.WebContextsService.destroySessionContext(WebContextsService.java:553)
        at org.apache.webbeans.web.context.WebContextsService.endContext(WebContextsService.java:228)
        at org.apache.webbeans.servlet.WebBeansConfigurationListener.sessionDestroyed(WebBeansConfigurationListener.java:197)
        at org.apache.catalina.session.StandardSession.expire(StandardSession.java:801)
        - locked <0x00000000fbb102b8> (a org.apache.catalina.session.StandardSession)
        at org.apache.catalina.session.StandardSession.isValid(StandardSession.java:659)
        at org.apache.catalina.session.PersistentManagerBase.swapIn(PersistentManagerBase.java:736)
        - locked <0x00000000fa5be668> (a java.lang.Object)
        at org.apache.catalina.session.PersistentManagerBase.findSession(PersistentManagerBase.java:488)
        at org.apache.catalina.connector.Request.doGetSession(Request.java:2909)
        at org.apache.catalina.connector.Request.getSession(Request.java:2374)
        at org.apache.catalina.connector.RequestFacade.getSession(RequestFacade.java:908)
        at org.apache.webbeans.web.context.WebContextsService.destroySessionContext(WebContextsService.java:553)
        at org.apache.webbeans.web.context.WebContextsService.endContext(WebContextsService.java:228)
        at org.apache.webbeans.servlet.WebBeansConfigurationListener.sessionDestroyed(WebBeansConfigurationListener.java:197)
        at org.apache.catalina.session.StandardSession.expire(StandardSession.java:801)
        - locked <0x00000000fbb10330> (a org.apache.catalina.session.StandardSession)
        at org.apache.catalina.session.StandardSession.isValid(StandardSession.java:659)
        at org.apache.catalina.session.PersistentManagerBase.swapIn(PersistentManagerBase.java:736)
        - locked <0x00000000fa5be668> (a java.lang.Object)
        at org.apache.catalina.session.PersistentManagerBase.findSession(PersistentManagerBase.java:488)
        at org.apache.catalina.connector.Request.doGetSession(Request.java:2909)
        at org.apache.catalina.connector.Request.getSession(Request.java:2374)
        at org.apache.catalina.connector.RequestFacade.getSession(RequestFacade.java:908)
        at org.apache.webbeans.web.context.WebContextsService.destroySessionContext(WebContextsService.java:553)
        at org.apache.webbeans.web.context.WebContextsService.endContext(WebContextsService.java:228)
        at org.apache.webbeans.servlet.WebBeansConfigurationListener.sessionDestroyed(WebBeansConfigurationListener.java:197)
        at org.apache.catalina.session.StandardSession.expire(StandardSession.java:801)
        - locked <0x00000000fbb103a8> (a org.apache.catalina.session.StandardSession)
        at org.apache.catalina.session.StandardSession.isValid(StandardSession.java:659)
        at org.apache.catalina.session.PersistentManagerBase.swapIn(PersistentManagerBase.java:736)
        - locked <0x00000000fa5be668> (a java.lang.Object)
        at org.apache.catalina.session.PersistentManagerBase.findSession(PersistentManagerBase.java:488)
        at org.apache.catalina.connector.Request.doGetSession(Request.java:2909)
        at org.apache.catalina.connector.Request.getSession(Request.java:2374)
        at org.apache.catalina.connector.RequestFacade.getSession(RequestFacade.java:908)
        at org.apache.webbeans.web.context.WebContextsService.destroySessionContext(WebContextsService.java:553)
        at org.apache.webbeans.web.context.WebContextsService.endContext(WebContextsService.java:228)
        at org.apache.webbeans.servlet.WebBeansConfigurationListener.sessionDestroyed(WebBeansConfigurationListener.java:197)
        at org.apache.catalina.session.StandardSession.expire(StandardSession.java:801)
        - locked <0x00000000fbb10420> (a org.apache.catalina.session.StandardSession)
        at org.apache.catalina.session.StandardSession.isValid(StandardSession.java:659)
        at org.apache.catalina.session.PersistentManagerBase.swapIn(PersistentManagerBase.java:736)
        - locked <0x00000000fa5be668> (a java.lang.Object)
        at org.apache.catalina.session.PersistentManagerBase.findSession(PersistentManagerBase.java:488)
        at org.apache.catalina.connector.Request.doGetSession(Request.java:2909)
        at org.apache.catalina.connector.Request.getSession(Request.java:2374)
        at org.apache.catalina.connector.RequestFacade.getSession(RequestFacade.java:908)
        at org.apache.webbeans.web.context.WebContextsService.destroySessionContext(WebContextsService.java:553)
        at org.apache.webbeans.web.context.WebContextsService.endContext(WebContextsService.java:228)
        at org.apache.webbeans.servlet.WebBeansConfigurationListener.sessionDestroyed(WebBeansConfigurationListener.java:197)
        at org.apache.catalina.session.StandardSession.expire(StandardSession.java:801)
        - locked <0x00000000fbb10498> (a org.apache.catalina.session.StandardSession)
        at org.apache.catalina.session.StandardSession.isValid(StandardSession.java:659)
        at org.apache.catalina.session.PersistentManagerBase.swapIn(PersistentManagerBase.java:736)
        - locked <0x00000000fa5be668> (a java.lang.Object)
        at org.apache.catalina.session.PersistentManagerBase.findSession(PersistentManagerBase.java:488)
        at org.apache.catalina.connector.Request.doGetSession(Request.java:2909)
        at org.apache.catalina.connector.Request.getSession(Request.java:2374)
        at org.apache.catalina.connector.RequestFacade.getSession(RequestFacade.java:908)
        at org.apache.webbeans.web.context.WebContextsService.destroySessionContext(WebContextsService.java:553)
        at org.apache.webbeans.web.context.WebContextsService.endContext(WebContextsService.java:228)
        at org.apache.webbeans.servlet.WebBeansConfigurationListener.sessionDestroyed(WebBeansConfigurationListener.java:197)
        at org.apache.catalina.session.StandardSession.expire(StandardSession.java:801)
        - locked <0x00000000fbb10510> (a org.apache.catalina.session.StandardSession)
        at org.apache.catalina.session.StandardSession.isValid(StandardSession.java:659)
        at org.apache.catalina.session.PersistentManagerBase.swapIn(PersistentManagerBase.java:736)
        - locked <0x00000000fa5be668> (a java.lang.Object)
        at org.apache.catalina.session.PersistentManagerBase.findSession(PersistentManagerBase.java:488)
        at org.apache.catalina.connector.Request.doGetSession(Request.java:2909)
        at org.apache.catalina.connector.Request.getSessionInternal(Request.java:2635)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:464)
        at org.apache.catalina.valves.rewrite.RewriteValve.invoke(RewriteValve.java:540)
        at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:651)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:137)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
        at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:651)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:407)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:754)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1376)
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        - locked <0x00000000f898c128> (a org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)

		






java.io.IOException: Unable to delete file [....ABCDE.session] which is no longer required
	at org.apache.catalina.session.FileStore.remove(FileStore.java:269)
	at org.apache.catalina.session.StoreBase.processExpires(StoreBase.java:189)
	at org.apache.catalina.session.PersistentManagerBase.processExpires(PersistentManagerBase.java:433)
	at org.apache.catalina.session.ManagerBase.backgroundProcess(ManagerBase.java:558)
	at org.apache.catalina.core.StandardContext.backgroundProcess(StandardContext.java:5406)
	at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1396)
	at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1400)
	at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1400)
	at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1368)
	at java.lang.Thread.run(Thread.java:748)
Comment 1 Holger Sunke 2018-03-13 11:21:11 UTC
Although it would likely solve this issue, I think it would not be desirable to synchronize the org.apache.catalina.session.FileStore.load(String)/.remove(String) methods.

Instead it would be better to prevent loading a session twice in a single thread.
Comment 2 Felix Schumacher 2018-03-14 13:40:55 UTC
Created attachment 35763 [details]
Test case that shows infinite recursion on session loading

The attached test case shows the described infinite recursion. It has to jump through a lot of hoops to accomplish this.
Comment 3 Felix Schumacher 2018-03-14 13:42:03 UTC
Created attachment 35764 [details]
Refactor part one to make fix more readable

Extract loading from store into private method
Comment 4 Felix Schumacher 2018-03-14 13:43:30 UTC
Created attachment 35765 [details]
Refactor part two to make fix more readable

Further extraction of functionality in private method to load sessions from store
Comment 5 Felix Schumacher 2018-03-14 13:44:12 UTC
Created attachment 35766 [details]
Refactoring part three to make fix more readable

Extract reactivation of sessions into private method
Comment 6 Felix Schumacher 2018-03-14 13:45:09 UTC
Created attachment 35767 [details]
Store currently loaded session in thread local storage to load it only once

Load sessions only once from store.
Comment 7 Holger Sunke 2018-03-14 14:33:59 UTC
Shouldn't the ThreadLocal cleanup sessionToSwapIn.remove(); be in a finally{..} block? (just in case)

A ThreadLocale stuck session would prevent garbage collection of webAppClassLoader if the app get's unloaded.
Comment 8 Felix Schumacher 2018-03-14 20:03:11 UTC
Created attachment 35768 [details]
Store currently loaded session in thread local storage to load it only once

Store currently loaded session in thread local storage to load it only once (guard thread local with a try catch block)
Comment 9 Felix Schumacher 2018-03-15 22:13:35 UTC
Thanks for the detailed report and feedback, it would be great, if you could check, whether this really fixes your problem.

Fixed in:
- trunk for 9.0.7 onwards
- 8.5.x for 8.5.30 onwards
- 8.0.x for 8.0.51 onwards
- 7.0.x for 7.0.86 onwards
Comment 10 Holger Sunke 2018-03-16 07:57:57 UTC
My problem is fixed, instead of endless "Session destroyed" and "IOException" log entry loops I now get a single such log entry only combined with a single IOException:

16.03.2018 08:43:31.540 [http-nio-8080-exec-1] DEBUG d.b.w.c.application.listener.ApplicationListener - Session destroyed: BB45287...; creationTime: 2018/03/16 08:13:45:201 MEZ; lastAccessTime: 2018/03/16 08:13:52:843 MEZ; usageTime: 7642 ms;
Mär 16, 2018 8:43:31 AM org.apache.catalina.session.PersistentManagerBase swapIn
SCHWERWIEGEND: Swapped session [BB45287089392C6B6B13AD5B51FD051A] is invalid
Mär 16, 2018 8:43:31 AM org.apache.catalina.session.PersistentManagerBase removeSession
SCHWERWIEGEND: Exception removing session  Unable to delete file [...BB45287089392C6B6B13AD5B51FD051A.session] which is no longer required
java.io.IOException: Unable to delete file [...\BB45287089392C6B6B13AD5B51FD051A.session] which is no longer required
	at org.apache.catalina.session.FileStore.remove(FileStore.java:269)
	at org.apache.catalina.session.PersistentManagerBase.removeSession(PersistentManagerBase.java:598)
	at org.apache.catalina.session.PersistentManagerBase.swapIn(PersistentManagerBase.java:725)
	at org.apache.catalina.session.PersistentManagerBase.findSession(PersistentManagerBase.java:494)



After that, the user gets a new session and can continute to work, without killing the JVM via OutOfMemoryError.

Thanks for the quick fix.