Expired Session timing issue leads to Warning: "Invalidating session {} found to be expired when requested"

[tsmortenson]

Jetty version(s)
9.4.52.v20230823 but the source of 10.x is also the same so we believe this issue persists. The issue is rare though so difficult to reproduce.

Jetty Environment
NA

Java version/vendor (use: java -version)

openjdk version "17.0.8.1" 2023-08-24
OpenJDK Runtime Environment Temurin-17.0.8.1+1 (build 17.0.8.1+1)
OpenJDK 64-Bit Server VM Temurin-17.0.8.1+1 (build 17.0.8.1+1, mixed mode, sharing)

OS type/version

MacOS 12.6.4, Ubuntu 20

Description

We have only seen it a few times, but every once in a while the SessionHandler.getSession() method will log a warning because an expired session was requested. It then correctly returns a null.

From looking through the code, it appears that the SessionHandler.scavenge() method is called at regular intervals to dispose sessions which have expired. The getSession() method also does the same check, but then logs the warning if it is expired.
There is a brief period of time where the session was still valid in the last scavenge() call, but expired when getSession() is called.

I think the logic here is correct. But shouldn't this warning just be a debug message at most? This does not indicate a problem in any way. If you want to detect sessions which are not being scavenged, then maybe show a warning only if it has been expired for longer than the interval that scavenging happens.

It would be nice to avoid this rather scary looking warning and stack trace.

How to reproduce?

Described above, This is the stack trace from the last time this happened.

WARN 2023-10-31 11:30:50.653 [fortress.http.org.eclipse.jetty.server.session ] Invalidating session node01jv0kou9frnmjuiuozl2hhxnc157 found to be expired when requested WARN 2023-10-31 11:30:50.654 [fortress.http.org.eclipse.jetty.server.session ] java.lang.IllegalStateException at org.eclipse.jetty.server.session.Session.beginInvalidate(Session.java:993) at org.eclipse.jetty.server.session.Session.invalidate(Session.java:934) at org.eclipse.jetty.server.session.SessionHandler.getSession(SessionHandler.java:918) at org.eclipse.jetty.server.session.SessionHandler.getHttpSession(SessionHandler.java:553) at org.eclipse.jetty.server.session.SessionHandler.checkRequestedSessionId(SessionHandler.java:1673) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1543) at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) at org.eclipse.jetty.server.handler.StatisticsHandler.handle(StatisticsHandler.java:181) at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) at org.eclipse.jetty.server.Server.handle(Server.java:516) at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487) at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732) at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479) at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:555) at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:410) at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:164) at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) at org.eclipse.jetty.util.thread.MonitoredQueuedThreadPool$1.run(MonitoredQueuedThreadPool.java:77) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) at java.base/java.lang.Thread.run(Thread.java:829)

[janbartel]

I'm happy to remove the stacktrace. That would have started showing up since I changed the Log.WARN (which looked like it was outputting the stacktrace, but it really wasn't) in this commit on 1 Feb 2020:

ecd0fe9#diff-5ed4c0ade753f9d5351ed97b6921580a23283270d72afb22097d7ab1ad4f2fe6

The Log.WARN has been there since this commit on 15 April 2016:
d28dffb

So as it's been there so long, I'm reluctant to remove the entire Log.WARN and change to a Log.DEBUG, but I could be persuaded ...

[janbartel]

@tsmortenson also don't forget that jetty-9 is at end of community support, so if I make this change, I'll be doing it in jetty-12, backporting to 11/10 and 9 will be on a best-effort basis with no release schedule attached.

[tsmortenson]

@janbartel Thank you. I am not expecting a change in Jetty9. I just wanted to be clear about that being where it had been found. Fixing this in later versions would be great. (Hopefully 10+)

I understand that it is a logged stack trace and not a thrown exception. Even with 9 we can work around it a bit by filtering the logs at the risk of missing other warnings. It is only an issue because logging warnings triggers internal support notfications.

[janbartel]

See PR #10847

[janbartel]

The github automatic close didn't happen on this issue when I merged #10847, so closing now.