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)
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.
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.
Created attachment 35764 [details] Refactor part one to make fix more readable Extract loading from store into private method
Created attachment 35765 [details] Refactor part two to make fix more readable Further extraction of functionality in private method to load sessions from store
Created attachment 35766 [details] Refactoring part three to make fix more readable Extract reactivation of sessions into private method
Created attachment 35767 [details] Store currently loaded session in thread local storage to load it only once Load sessions only once from store.
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.
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)
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
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.