EzDevInfo.com

weld

Template antimatter for Node.js (Browsers too!)

WELD + GF4 + SessionScoped: Sometimes wrong bean?

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 @SessionScoped bean.
Every instance of the @SessionScoped bean 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 @SessionScoped beans 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...

weld

The setup

The application

The implementation

Observed behavior

The logs

The code

Additional information

The actual question

update