TL;DR We get @SessionScoped bean instances injected that have the content of another session
lately we have been experiencing serious problems with two of our customer systems. Our customers are running two independent instances of the same JSF 2.2 application on two machines having a Glassfish 4.0 Server with WELD 2.0.5 (hail to the memory leak!).
Some users have been reporting problems that after e.g. submitting a form the response shows another user name than the one who initially logged in. Since we were unable to reproduce this behaviour in our development and testing environments, we started to grab log data from the productive systems.
What were we logging?
On our first attempt we started logging which user conducted which action from which client at some time. After crawling through the logs we found sequences like this:
Time Client User Action
.............................
t=0 ClientA UserA Login
t=1 ClientA UserA Logoff
t=2 ClientB UserB Login
t=3 ClientB UserB ActionA
t=4 ClientB *UserA* ActionB
t=5 ClientB UserB Logoff
Whereas the session of the replacing user (here User A) was not always over before the replacement happened (sometimes resulting in one user logging out another one...). So where is the currently logged in user stored? We store it as a property in a @SessionScoped bean being injected into @RequestScoped beans wherever we need this information. This led us to the theory that the @SessionScoped beans sometimes get mixed up.
@Named
@javax.enterprise.context.SessionScoped
public class SessionStateBean {
private User user;
public void setUser(...) { }
public User getUser() { }
}
Therefore on our second attempt we extended the log data by the following features:
- We started storing the user name inside the HTTP session and compared it on every request with the value coming from the
@SessionScopedbean. - Every instance of the
@SessionScopedbean received its own UUID and logged when the bean was constructed & destroyed as well as when the user property was changed. We know that it is possible that@SessionScopedbeans can have multiple proxies, be passivated, etc., but we gave it a try.
Regarding the first log feature we started seeing sequences showing actual differences between the user name coming from the session scoped bean and the value being stored inside the HTTP session:
Time Session Client User Action
.............................
t=0 SessA ClientA UserA Login
t=1 SessA ClientA UserA Logoff
t=2 SessB ClientB UserB Login
t=3 SessB ClientB UserB ActionA
t=4 |SessB ClientB *UserA* ActionB
+-> SessionScope != Session
t=5 SessB ClientB UserB Logoff
Taking all requests being processed into account, the ones where the session scope value does not match the session value are approx. 1 out of 60 to 150 requests.
More interesting is what happened with the @SessionScoped bean instances. Since we are tracking @PostConstruct & @PreDestroy events, sequences like the following were observed:
Time Session Bean Action UserValue
................................
t=0 SessA BeanA Construct (null)
t=1 SessA BeanA SetUser UserA // login
t=2 SessA BeanA SetUser (null) // logout
t=3 SessA BeanA Destroy (null)
// so far so good, now it gets interesting
t=4 SessB BeanA SetUser UserB // login
t=5 SessB BeanA SetUser (null) // logout
t=6 SessC BeanA SetUser UserC // login
t=7 SessC BeanA SetUser (null) // logout
t=8 SessD BeanA SetUser UserD // login
t=9 SessD BeanA SetUser (null) // logout
We did not expect that sometimes after the @PreDestroy event bean instances get reused without going through the life cycle of construction and destruction. Taking all logged bean instances into account this happens with approx. 1 bean out of 500 (System A) to 4000 (System B). This is not always happening when the session scope value and the HTTP session value differ, but always when we see such a bean instance being reused it is when the values are different.
Initially we assumed that these events are more likely to occur after the server has been under load for a while, but this turned out not to be true. Sometimes they occur some hours after the last server restart and sometimes after two weeks.
Searching the internet for these issues we were not able to find actual traces on other people experiencing the same problems or known bugs in either WELD (best trace, but wrong version), Glassfish, Grizzly (best trace, but too old), JSF, etc.
So our question is: Is there anyone who ever has experienced a similar problem? Is this odd behaviour somehow a known bug we just tried to identify in the wrong spot? Is there even an actual fix? Any hint is gladly appreciated!
Update: We found out that if we restart the whole machine the described behaviour is gone for around two weeks. If we just restart Glassfish it's a matter of hours until the odd behaviour is back. Seriously, what can affect Glassfish or the JVM that badly such that only a machine reboot changes the behaviour?
Currently we are bypassing the problem by putting all data we kept in the @SessionScoped bean directly into the HTTP session and so far it seems to work fine. But that approach is so clumsy...
@sessionScopean option for you? - kolossus@SessionScopeis not an option to us, since it does not play nicely together with all the other CDI annotations. - marius.7383@SessionScopedbeans are for sure annotated with@javax.enterprise.context.SessionScopedand not@javax.faces.bean.SessionScoped? - Baldyjavax.enterprise.context.SessionScoped. What I just noted as well is, that the bean does not have an explicitserialVersionUID. Is that important for@SessionScopedbeans? - marius.7383