Request getSession() method throws IllegalStateException when Session exists #4888
Comments
…ession if found Instead of logging and exception and returning null, if an existing Session is found in the session cache when attempting to add a new session then the existing session is used instead and returned
|
Please also post your log output that shows the stack traces. |
|
I am unable to post the stack trace output as it's on a proprietary system so I'm not authorized to do so. |
…ession if found Instead of logging and exception and returning null, if an existing Session is found in the session cache when attempting to add a new session then the existing session is used instead and returned Signed-off-by: Christopher L. Shannon <christopher.l.shannon@gmail.com>
|
PR submitted: #4889 |
|
@cshannon any way you can sanitize the log so you would be permitted to post at least parts of it? Ideally I'd like to see log output with org.eclipse.jetty.server.session log level set to DEBUG so it's possible to trace the lifecycle of session ids. I'm very interested in getting a reproduction for this so we can thoroughly understand the race condition: I would rather that we made code changes only after we really understand the problem, otherwise we're patching in the dark and may cause a lot of unintended consequences (the servlet spec sessions are a real hornets nest!). |
|
Also, in the application where you've seen this happen, can you describe any more about the handling of requests? You mention it happens when there is a flurry of requests to the server, IIUC these requests all have a cookie with a session id that used to exist but is now no longer existing (or valid?). Is there any forwarding/including or async handling in the path of the handling of these requests? |
|
There may be some forwarding, I'm not sure as we aren't implementing it and are using Spring MVC and Spring Security so under the covers their filters and dispatcher servlets may be doing some async things to contribute to this. As I said, it seems to primarily happen on session expiration when the browser fires off a bunch of requests at the same time for the application but I haven't been able to reproduce it on demand yet. But it is happening pretty often in our logs. Also, it does seem to happen sometimes on server restart so in that case it would be requests with the same cookie with a session id that no longer exists as they come from the same browser session that is opened. Usually it's the Spring Security filter that blows up when trying to access the session. In terms of sanitizing the log, I was able to quickly reproduce the same stack trace that I am seeing from a unit test. This leaves out the spring/my custom filters but demonstrates what I'm seeing. `java.lang.IllegalStateException: Session node05mh7i3r1hgeu1j44ne3yw04ox0 already in cache 2020-05-19 09:07:10.456:WARN:oejs.HttpChannel:qtp22805895-21: /login |
|
Can I see the source of the test please? |
|
The source for the test isn't very useful as it was just created to get a sample stack trace and not to demonstrate the error happening. For the test I just took an existing unit test in Jetty (RequestDispatchedSessionTest) and added a filter to make a call to Request.getSession(). Since it's not easy to reproduce I temporarily changed the condition inside AbstractSessionCache in the add method to always throw that IllegalStateException so it would replicate the stack trace. If really necessary I can try and get the logs with the real stack traces (sanitized of course) that include the Spring filters and post them here but I won't be back in the office again until next week when I can access that system again so it would be next week. However, the stack trace above is a good representation of it so I'm not sure the real stack traces would provide anymore value. |
|
@janbartel - From what I can tell, I think the race condition is happening for the requests between the doScope() call of SessionHandler and the call to Request#getSession(). If multiple requests come in for an existing sessionId (same cookie) at the same time (server restart, invalidation etc) then when they hit the SessionHandler the doScope() method is supposed to set the existing Session on the request. However at the time the requests hit doScope() the session doesn't exist so the Request has a null _session variable. However, one of the requests finishes first and creates the session so when another request gets to the getSession() method inside Request it sees that the local variable _session is null and tries to create a new one and gets the error as it is using the same id from the cookie. I could be wrong but that seems to be the behavior I'm seeing. I am still trying to figure out a way to replicate the issue in a test for real. My PR has a test but as I said it simulates the issue to verify the fix works but doesn't demonstrate the race condition that I think is there. |
|
Also, if you don't like returning the existing session as my patch does, it could be simplified to go back to the behavior of 9.4.20 and always return a new session but just not add it to the cache. If you run my test that is part of #4889 against 9.4.20 you will see it will fail but it fails because the two sessions returned are not the same object but they share the same Id. This behavior has worked for our application for many years and only after updating when the cache implementation change did this issue show up. |
|
Well, that behaviour was wrong, which is why we fixed it. Let's see if we can't come up with a solution that works also for your application. I would really like to see those (sanitized) logs. I'd also like a general description of how you're using spring security, and any config params that specifically deal with sessions. |
|
Right, I assumed the behavior of returning a new Session when one exists is wrong which is why my patch will return the existing Session instead of null. It makes sense to me to return the existing Session if we have it vs logging an error and returning null. I can see what I can do next week with the logs, but still may not be able to provide a version easily. The issue is most noticeable with Spring Security but I was also able to get it to happen on server restarts by making the call to getSession() in my own filter last week. (still using Spring MVC but not Spring Security) That stack trace without Spring Security more or less replicates what I already pasted in this issue minus the Spring MVC parts. So I may try and see if if I can provide a stack trace with/without Spring Security to see the difference. As I said, seems to happen sometimes on session expiration and sometimes on server restart when the application is still open and hitting the server. For your other question, general description is Spring security is set up for filtering on URLs and sessions are enabled. So every request gets authenticated and Spring security also calls off to the session (I assume to cache data in there). Concurrent sessions are enabled so part of the stack trace shows the ConcurrentSessionControlStrategy in use. (not sure if something with this has anything to do with it in terms of making it more likely or not to happen) Obviously the best thing might be to figure out a way to write a test to reproduce the issue but that may not be easy if it's truly a race condition unfortunately. |
|
@cshannon ideally it would be good to get a simple webapp that can at least sometimes reproduce the issue and then we can work with that. Going back to your app, I'd also like to know what the settings are for spring security, can you please post the config selections matching the ones mentioned on this page: https://www.baeldung.com/spring-security-session. I am sceptical about this so called "concurrent sessions" approach - I will need to look into the code of spring security to know what they actually mean by that. |
|
@janbartel - I agree, next week when I'm back in the office I will do some more digging and see if i can narrow down the root cause to create a reproducible test case. One thing I completely forgot to mention is there is also a WebSocket connection. Not sure if that is part of it or not (nothing from Websockets has shown up in the stack trace) but sessions could be involved there too. In terms of Spring Security, the session configuration is set to "always" and concurrent sessions are set to 5. There is a session timeout configured through the web.xml and is pretty short (i think a few minutes). Ideally I'd like to come up with a test case without Spring and Spring Security to make it easier to debug. In the meantime it looks like Jetty allows plugging in a custom SessionHandler and SessionCache pretty easily so I can probably override the defaults with something that works for my use case to get past the issue until figured out. |
|
Quick update, I haven't been able to come up with a webapp yet to reliably reproduce the issue. I have to move on to some other things but I'll try and get back to it when I have time. In terms of logs, it's still going to be a bit tough to move the logs but as I said, the stack trace I already posted it exactly what I'm seeing so the most useful thing would be a reliable test case. In the meantime I have come up with a workaround for my use case to get around the issue. |
|
I'm just tuning in to this issue to see if I can help. @janbartel the |
|
Of course the problem with allowing an async thread to call getSession is that if a request is not dispatched then you don't know what context to get the session from. |
|
@janbartel and I have walked through this and there is something about your usage that we just don't understand:
If a session does not exist, then a new one must not be made with the same session id - as that could result in all sorts of security issues. We have only very limited cases in which we will reuse a session ID and they basically are involved only with cross context dispatch. We will reuse a request session ID IFF the session is in use or this request has already created a session with the ID in another context.
Once a request passes doScope with a null _session, then a session for that ID should never EVER be created. So we have to work out how your setup is creating a new session for the old session ID. What How is it that a session ID that didn't exist suddenly exists again??? |
|
@gregw I think I might have bumped into a similar error just today with Weld servlet test using Jetty 9.4.31. The test in question is this one.
FTR the test used to work with older Jetty (tests were using |
|
@manovotn thanks for that repro test case and stack trace. I think I can see what is happening, but you will have to confirm my theory with your greater knowledge of weld. I believe the request comes in either without a session id or at least an unknown session id. The app calls Request.getSession(true) and we are in the process of creating the new session [A]. We have to call any HttpSessionListeners after we've made the session. One of these listeners has a reference to the Request, and again calls Request.getSession(true). As we have not yet returned from creating the session at [A] the Request does not know about this new session, so will attempt to create another one [B]. When we made the first session at [A], we set the new id we are using onto the Request as the __NEW_SESSION_ID attribute so that it can be retrieved by any later cross-context dispatches that want to create a session. So now at [B], we check the __NEW_SESSION_ID attribute and voila, it is set so we try to reuse it! This all hinges on the HttpSessionListener having a path to referencing the Request - is this possible in weld? |
Request.getSession() Signed-off-by: Jan Bartel <janb@webtide.com>
I'll have to debug it to be able to say more. The app (the test archive itself) is pretty dumb and doesn't itself create session. What's going to create session is Weld trying to initialize session context to store session bean in (
I'll try tomorrow (have to leave now, it's getting a bit late), anything special I need to know/do to build jetty snapshot? |
At this point you have it compiled against the branch that PR #5220 is based on. You can find the artifacts, including jetty-home (and the older jetty-distribution) in your Use version |
|
@janbartel only just got to it. I've run Weld test with your fix and can confirm that it works. |
|
Yeah, I think this issue should be closed. |
|
You can close the issue, as I believe it's solved now. I implemented a workaround before so I would need to go back and remove that to specifically test the fix but based on looking at it plus with Weld being fixed I think this should be closed. If something else pops up again I'll open a new issue as that would mean a different cause anyways. |
|
thanks |
Jetty version: 9.4.27
Java version: Java 11
OS type/version: Fedora 31
Description
An existing issue, #4156, attempted to fix this problem but seems to only have fixed it in some cases. I am still seeing a very similar stack trace as #4156 when the server is trying to add a Session to the cache that is found to already exist. The same IllegalStateException is thrown and and a null session is returned leading to a NPE later in the chain.
The main difference is this is occurring when calling Request#getSession(true) directly from a custom Servlet filter to access a Session. I'e also seen it happen with other libraries that use filters like Spring Security. The exact cause is hard to pinpoint and reproduce because it appears to be a race condition when several requests come in at once. I have noticed it primarily on server restarts or Session expirations when a browser submits a bunch of requests back to the server with an existing id set and it has to be recreated.
Proposed Solution:
I think the best approach would be to change the cache add so that when Request#getSession() is called and an existing session is found it will be used instead of logging an exception and returning null. A new method should be added to the Session cache that can simply use putIfAbsent and return an existing Session if already there. (Note that in 9.4.20 a new Session was actually still returned which I think is wrong)
While it's somewhat hard to reproduce the issue because I believe there's a race condition, I have written a test that directly uses the SessionHandler to replicate the condition that I am seeing to validate my fix. I will be submitting a PR with my test and fix shortly.
The text was updated successfully, but these errors were encountered: