Race condition in session establishment for concurrent requests

[smarquard]

Describe the bug

Multiple concurrent requests to an Opencast endpoint (in this case POST to the LTI servlet) can lead to a race condition inside jetty where one of the requests succeeds and the others fail to establish a session properly, returning a null session object.

It seems a similar issue to this one: jetty/jetty.project#4888

The full stack trace is:

2024-01-04 09:06:02,440 WARN o.e.j.s.session [qtp971424836-137] 
java.lang.IllegalStateException: Session node01tqlb7lrsg0jjsjgweypcu9ad54255~ROOT#opencast already in cache
	at org.eclipse.jetty.server.session.AbstractSessionCache.add(AbstractSessionCache.java:467) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.server.session.SessionHandler.newHttpSession(SessionHandler.java:770) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.server.Request.getSession(Request.java:1630) ~[!/:9.4.52.v20230823]
	at javax.servlet.http.HttpServletRequestWrapper.getSession(HttpServletRequestWrapper.java:221) ~[!/:4.0.4]
	at org.ops4j.pax.web.service.spi.servlet.OsgiHttpServletRequestWrapper.getSession(OsgiHttpServletRequestWrapper.java:114) ~[!/:?]
	at javax.servlet.http.HttpServletRequestWrapper.getSession(HttpServletRequestWrapper.java:221) ~[!/:4.0.4]
	at javax.servlet.http.HttpServletRequestWrapper.getSession(HttpServletRequestWrapper.java:221) ~[!/:4.0.4]
	at org.springframework.security.web.context.HttpSessionSecurityContextRepository$SaveToSessionResponseWrapper.createNewSessionIfAllowed(HttpSessionSecurityContextRepository.java:340) ~[?:?]
	at org.springframework.security.web.context.HttpSessionSecurityContextRepository$SaveToSessionResponseWrapper.saveContext(HttpSessionSecurityContextRepository.java:281) ~[?:?]
	at org.springframework.security.web.context.HttpSessionSecurityContextRepository.saveContext(HttpSessionSecurityContextRepository.java:104) ~[?:?]
	at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:87) ~[?:?]
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342) ~[?:?]
	at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:113) ~[?:?]
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342) ~[?:?]
	at org.springframework.security.web.authentication.rememberme.RememberMeAuthenticationFilter.doFilter(RememberMeAuthenticationFilter.java:146) ~[?:?]
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342) ~[?:?]
	at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:54) ~[?:?]
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342) ~[?:?]
	at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:45) ~[?:?]
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342) ~[?:?]
	at org.springframework.web.filter.CompositeFilter$VirtualFilterChain.doFilter(CompositeFilter.java:98) ~[?:?]
	at org.springframework.security.oauth.provider.filter.ProtectedResourceProcessingFilter.onValidSignature(ProtectedResourceProcessingFilter.java:87) ~[?:?]
	at org.springframework.security.oauth.provider.filter.OAuthProviderProcessingFilter.doFilter(OAuthProviderProcessingFilter.java:168) ~[?:?]
	at org.springframework.web.filter.CompositeFilter$VirtualFilterChain.doFilter(CompositeFilter.java:102) ~[?:?]
	at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilter(BasicAuthenticationFilter.java:150) ~[?:?]
	at org.springframework.web.filter.CompositeFilter$VirtualFilterChain.doFilter(CompositeFilter.java:102) ~[?:?]
	at org.springframework.security.web.authentication.www.DigestAuthenticationFilter.doFilter(DigestAuthenticationFilter.java:115) ~[?:?]
	at org.springframework.web.filter.CompositeFilter$VirtualFilterChain.doFilter(CompositeFilter.java:102) ~[?:?]
	at org.springframework.web.filter.CompositeFilter.doFilter(CompositeFilter.java:82) ~[?:?]
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342) ~[?:?]
	at org.springframework.security.web.authentication.ui.DefaultLoginPageGeneratingFilter.doFilter(DefaultLoginPageGeneratingFilter.java:91) ~[?:?]
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342) ~[?:?]
	at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:183) ~[?:?]
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342) ~[?:?]
	at org.springframework.web.filter.CompositeFilter$VirtualFilterChain.doFilter(CompositeFilter.java:98) ~[?:?]
	at org.springframework.web.filter.CompositeFilter.doFilter(CompositeFilter.java:82) ~[?:?]
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342) ~[?:?]
	at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:105) ~[?:?]
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342) ~[?:?]
	at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:87) ~[?:?]
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342) ~[?:?]
	at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:192) ~[?:?]
	at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:160) ~[?:?]
	at org.opencastproject.kernel.security.SecurityFilter.doFilter(SecurityFilter.java:141) ~[?:?]
	at org.ops4j.pax.web.service.spi.servlet.OsgiInitializedFilter.doFilter(OsgiInitializedFilter.java:176) ~[!/:?]
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[!/:9.4.52.v20230823]
	at org.ops4j.pax.web.service.jetty.internal.PaxWebFilterHolder.doFilter(PaxWebFilterHolder.java:208) ~[!/:?]
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1626) ~[!/:9.4.52.v20230823]
	at org.opencastproject.kernel.security.OrganizationFilter.doFilter(OrganizationFilter.java:154) ~[?:?]
	at org.ops4j.pax.web.service.spi.servlet.OsgiInitializedFilter.doFilter(OsgiInitializedFilter.java:176) ~[!/:?]
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[!/:9.4.52.v20230823]
	at org.ops4j.pax.web.service.jetty.internal.PaxWebFilterHolder.doFilter(PaxWebFilterHolder.java:208) ~[!/:?]
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1626) ~[!/:9.4.52.v20230823]
	at org.opencastproject.kernel.filter.https.HttpsFilter.doFilter(HttpsFilter.java:90) ~[?:?]
	at org.ops4j.pax.web.service.spi.servlet.OsgiInitializedFilter.doFilter(OsgiInitializedFilter.java:176) ~[!/:?]
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[!/:9.4.52.v20230823]
	at org.ops4j.pax.web.service.jetty.internal.PaxWebFilterHolder.doFilter(PaxWebFilterHolder.java:208) ~[!/:?]
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1626) ~[!/:9.4.52.v20230823]
	at org.opencastproject.kernel.rest.CleanSessionsFilter.doFilter(CleanSessionsFilter.java:104) ~[?:?]
	at org.ops4j.pax.web.service.spi.servlet.OsgiInitializedFilter.doFilter(OsgiInitializedFilter.java:176) ~[!/:?]
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:201) ~[!/:9.4.52.v20230823]
	at org.ops4j.pax.web.service.jetty.internal.PaxWebFilterHolder.doFilter(PaxWebFilterHolder.java:208) ~[!/:?]
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1626) ~[!/:9.4.52.v20230823]
	at org.ops4j.pax.web.service.spi.servlet.OsgiFilterChain.doFilter(OsgiFilterChain.java:100) ~[!/:?]
	at org.ops4j.pax.web.service.jetty.internal.PaxWebServletHandler.doHandle(PaxWebServletHandler.java:320) ~[!/:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:600) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:505) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:191) ~[!/:9.4.52.v20230823]
	at org.ops4j.pax.web.service.jetty.internal.PrioritizedHandlerCollection.handle(PrioritizedHandlerCollection.java:96) ~[!/:?]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:137) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [!/:9.4.52.v20230823]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [!/:9.4.52.v20230823]
	at java.lang.Thread.run(Thread.java:829) [?:?]

To Reproduce

This showed up in our Opencast 14.x production system with customisations to support LTI Deep Linking, with multiple embedded LTI content launches on the same page in the LMS. It happens the first time around, when the browser sends an old JSESSION id cookie and Opencast is attempting to establish a new session. It doesn't happen when there's no JSESSIONID cookie sent at all (e.g. incognito mode browser) or when there is already a valid Opencast session established by a prior launch. Hence, refreshing the containing page in the LMS makes the problem appear to go away as all the launches succeed.

Server environment:
Opencast 14.x, admin+presentation node, Karaf 4.4.4 with jetty 9.4.52.v20230823

[smarquard]

Here is a python script raceme.zip which reproduces this on stable.opencast.org, with results like this - the script ends when a 500 internal server error is received, and the two related stack traces can be seen in

https://stable.opencast.org/log/opencast.log

# python raceme.py 
URL https://stable.opencast.org/lti/player/id5 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id4 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id2 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id1 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id3 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id2 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id1 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id3 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id5 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id4 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id3 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id2 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id1 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id4 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id5 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id1 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id2 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id3 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id5 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id4 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id1 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id3 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id4 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id2 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id5 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id4 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id1 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id2 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id5 returned 302 redirect to https://stable.opencast.org/login.html
URL https://stable.opencast.org/lti/player/id3 returned 500 FAILED

Done after 29 requests.

2024-01-05T15:57:33,198 | WARN  | (JettyAwareLogger:607) - 
java.lang.IllegalStateException: Session node1704466652.76842701tqlb7lrsg0jjxjgweypcu9ad54255~ROOT#opencast already in cache
	at org.eclipse.jetty.server.session.AbstractSessionCache.add(AbstractSessionCache.java:467) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.server.session.SessionHandler.newHttpSession(SessionHandler.java:770) ~[!/:9.4.52.v20230823]
	at org.eclipse.jetty.server.Request.getSession(Request.java:1630) ~[!/:9.4.52.v20230823]
	at javax.servlet.http.HttpServletRequestWrapper.getSession(HttpServletRequestWrapper.java:221) ~[!/:4.0.4]

and

2024-01-05T15:57:33,203 | WARN  | (JettyAwareLogger:607) - /lti/player/id3
java.lang.IllegalStateException: Create session failed
	at org.eclipse.jetty.server.Request.getSession(Request.java:1632) ~[?:?]
	at javax.servlet.http.HttpServletRequestWrapper.getSession(HttpServletRequestWrapper.java:221) ~[!/:4.0.4]
	at org.ops4j.pax.web.service.spi.servlet.OsgiHttpServletRequestWrapper.getSession(OsgiHttpServletRequestWrapper.java:114) ~[?:?]
	at org.ops4j.pax.web.service.spi.servlet.OsgiHttpServletRequestWrapper.getSession(OsgiHttpServletRequestWrapper.java:103) ~[?:?]
	at javax.servlet.http.HttpServletRequestWrapper.getSession(HttpServletRequestWrapper.java:229) ~[!/:4.0.4]

Note that it doesn't matter for this purpose that the LTI payload is not present. It's simply about establishing an opencast session, whether authenticated or not.