1 Reply Latest reply on Sep 20, 2010 6:51 PM by gthorburn

SessionSyncronization and passivation

gthorburn Sep 2, 2010 10:07 PM

Hi,

I have been working with SFSB's/SessionSyncronization and timeout settings during a migration to EJB3/JBoss 5.1.0 from EJB2.1/JBoss4.2.2, and have encountered a problem around passivation and session syncronization. I have implemented two simple SFSB (one with SessionSyncronization, one without) as a test harness (All beans are EJB3, on JBoss 5.1.0). The beans just system out on method calls:

@Stateful
public class SyncBean implements SyncBeanLocal, SessionSynchronization
{
    public SyncBean() {}

    public void afterBegin( ) throws EJBException, RemoteException
    {
        System.out.println("SyncBean afterBegin()");
    }

    public void afterCompletion( boolean arg0 ) throws EJBException, RemoteException
    {
        System.out.println("SyncBean afterCompletion()");
    }

    public void beforeCompletion( ) throws EJBException, RemoteException
    {
        System.out.println("SyncBean beforeCompletion()");
    }    

    //Method on business interface
    public void beanMethod()
    {
        System.out.println("SyncBean method called");
    }

    @Remove
    public void remove()
    {
        System.out.println("Removing SyncBean");
    }

    @PrePassivate
    public void passivate()
    {
         System.out.println("Passivating SyncBean");
    }

    @PostActivate
    public void postActivate()
    {
         System.out.println("Activating SyncBean");
    }
}

I have also made a change to the ejb3-interceptors-aop.xml to set the idleTimeoutSeconds to a small value, for debug/test purposes:

<domain name="Stateful Bean" extends="Base Stateful Bean" inheritBindings="true">
     ...
     @org.jboss.ejb3.annotation.CacheConfig (maxSize=100000, idleTimeoutSeconds=10, removalTimeoutSeconds=86400)

And added debug output for StatefulSessionFilePersistenceManager (jboss-log4j.xml):

<category name="org.jboss.ejb3.cache.simple.StatefulSessionFilePersistenceManager">
     <priority value="DEBUG"/>
</category>

From an existing transaction, The following is run:

    SyncBeanLocal testSessionSync = null;
    NoSyncBeanLocal testNoSessionSync = null;
    
    try
    {
        InitialContext ic = new InitialContext( );
        Object sync = ic.lookup( "ejb/SyncBean" );
        testSessionSync = (SyncBeanLocal) sync;
        Object noSync = ic.lookup( "ejb/NoSyncBean" );
        testNoSessionSync = (NoSyncBeanLocal) noSync;
    }
    catch( NamingException e )
    {
        System.out.println("Failed to locate beans");
    }
    
    testNoSessionSync.beanMethod( );         //Works fine
    testSessionSync.beanMethod( );           //Works fine
    
    doOtherWork();                           //Loop to kill time
    
    testNoSessionSync.beanMethod( );         //Works fine
    testSessionSync.beanMethod( );           //"javax.ejb.NoSuchEJBException"

The doOtherWork() method is a simple incrementing loop to kill time and is local to the class. No other transactions are started.

The bean without SessionSyncronization works as expected. After the method on the business interface is completed, it is passivated during the doOtherWork() method (the method exceeded the idleTimeoutSeconds), and is activated after the method returns without error. The bean that implements SessionSyncronization does not passivate, and the call after the doOtherWork() method is completed throws a "javax.ejb.NoSuchEJBException: Could not find stateful bean:" error.

When I increase the idleTimeoutSeconds to be greater than the time taken in doOtherWork(), the SessionSyncronization bean works without error.

Am I missing something around the behaviour of SessionSyncronization and passivation? I would expect that the bean is not passivated (it is considered in use after the afterBegin callback?), but throwing a NoSuchEJBException does not seem correct.

From the log it seems the container actually passivates the bean after the error is thrown & afterCompletion method is run. beforeCompletion does not appear to be called. Log copied below:

2010-09-03 09:51:27,191 INFO  [STDOUT] (ClientSession Thread) NoSyncBean method called. 
2010-09-03 09:51:27,192 INFO  [STDOUT] (ClientSession Thread) SyncBean afterBegin()
2010-09-03 09:51:27,192 INFO  [STDOUT] (ClientSession Thread) SyncBean method called.
2010-09-03 09:51:27,192 INFO  [STDOUT] (ClientSession Thread) doOtherWork() - Started
2010-09-03 09:51:38,660 DEBUG [org.jboss.ejb3.cache.simple.StatefulSessionFilePersistenceManager] (SFSB Passivation Thread - jboss.j2ee:ear=App.ear,jar=UtilsEJB.jar,name=NoSyncBean,service=EJB3) Attempting to passivate; id=5c4o03y-jjwh8j-gdm5d5bw-1-gdm5hy36-ah
2010-09-03 09:51:38,663 INFO  [STDOUT] (SFSB Passivation Thread - jboss.j2ee:ear=App.ear,jar=UtilsEJB.jar,name=NoSyncBean,service=EJB3) Passivating NoSyncBean
2010-09-03 09:51:38,663 DEBUG [org.jboss.ejb3.cache.simple.StatefulSessionFilePersistenceManager] (SFSB Passivation Thread - jboss.j2ee:ear=App.ear,jar=UtilsEJB.jar,name=NoSyncBean,service=EJB3) Saving session state to: E:\JBoss\jboss-5.1.0.GA_App_2.0\server\default\tmp\sessions\NoSyncBean-gdm5ergx-9w\5c4o03y-jjwh8j-gdm5d5bw-1-gdm5hy36-ah.ser
2010-09-03 09:51:38,667 DEBUG [org.jboss.ejb3.cache.simple.StatefulSessionFilePersistenceManager] (SFSB Passivation Thread - jboss.j2ee:ear=App.ear,jar=UtilsEJB.jar,name=NoSyncBean,service=EJB3) Passivation complete; id=5c4o03y-jjwh8j-gdm5d5bw-1-gdm5hy36-ah
2010-09-03 09:52:14,546 INFO  [STDOUT] (ClientSession Thread) doOtherWork() - Completed
2010-09-03 09:52:14,547 DEBUG [org.jboss.ejb3.cache.simple.StatefulSessionFilePersistenceManager] (ClientSession Thread) Attempting to activate; id=5c4o03y-jjwh8j-gdm5d5bw-1-gdm5hy36-ah
2010-09-03 09:52:14,547 DEBUG [org.jboss.ejb3.cache.simple.StatefulSessionFilePersistenceManager] (ClientSession Thread) Reading session state from: E:\JBoss\jboss-5.1.0.GA_App_2.0\server\default\tmp\sessions\NoSyncBean-gdm5ergx-9w\5c4o03y-jjwh8j-gdm5d5bw-1-gdm5hy36-ah.ser
2010-09-03 09:52:14,547 DEBUG [org.jboss.ejb3.cache.simple.StatefulSessionFilePersistenceManager] (ClientSession Thread) Removing passivated state file: E:\JBoss\jboss-5.1.0.GA_App_2.0\server\default\tmp\sessions\NoSyncBean-gdm5ergx-9w\5c4o03y-jjwh8j-gdm5d5bw-1-gdm5hy36-ah.ser
2010-09-03 09:52:14,551 INFO  [STDOUT] (ClientSession Thread) Activating NoSyncBean
2010-09-03 09:52:14,552 INFO  [STDOUT] (ClientSession Thread) NoSyncBean method called. 
2010-09-03 09:52:14,552 DEBUG [org.jboss.ejb3.cache.simple.StatefulSessionFilePersistenceManager] (ClientSession Thread) Attempting to activate; id=5c4o03y-jjwh8j-gdm5d5bw-1-gdm5hy30-ag
2010-09-03 09:52:14,553 ERROR [org.jboss.aspects.tx.TxPolicy] (ClientSession Thread) javax.ejb.NoSuchEJBException: Could not find stateful bean: 5c4o03y-jjwh8j-gdm5d5bw-1-gdm5hy30-ag
2010-09-03 09:52:14,554 DEBUG [org.jboss.ejb3.cache.simple.StatefulSessionFilePersistenceManager] (ClientSession Thread) Attempting to passivate; id=5c4o03y-jjwh8j-gdm5d5bw-1-gdm5hss2-ad
2010-09-03 09:52:14,559 INFO  [STDOUT] (ClientSession Thread) Passivating ConnectionBean
2010-09-03 09:52:14,560 DEBUG [org.jboss.ejb3.cache.simple.StatefulSessionFilePersistenceManager] (ClientSession Thread) Saving session state to: E:\JBoss\jboss-5.1.0.GA_App_2.0\server\default\tmp\sessions\ConnectionBean-gdm5erq4-9y\5c4o03y-jjwh8j-gdm5d5bw-1-gdm5hss2-ad.ser
2010-09-03 09:52:14,566 DEBUG [org.jboss.ejb3.cache.simple.StatefulSessionFilePersistenceManager] (ClientSession Thread) Passivation complete; id=5c4o03y-jjwh8j-gdm5d5bw-1-gdm5hss2-ad
2010-09-03 09:52:14,566 ERROR [org.jboss.aspects.tx.TxPolicy] (ClientSession Thread) javax.ejb.NoSuchEJBException: Could not find Stateful bean: 5c4o03y-jjwh8j-gdm5d5bw-1-gdm5hss2-ad
2010-09-03 09:52:14,567 ERROR [STDERR] (ClientSession Thread) com.dss.client.comm.DSSException: Could not find Stateful bean: 5c4o03y-jjwh8j-gdm5d5bw-1-gdm5hss2-ad
2010-09-03 09:52:14,567 INFO  [STDOUT] (ClientSession Thread) SyncBean afterCompletion()
2010-09-03 09:52:14,567 DEBUG [org.jboss.ejb3.cache.simple.StatefulSessionFilePersistenceManager] (ClientSession Thread) Attempting to passivate; id=5c4o03y-jjwh8j-gdm5d5bw-1-gdm5hy30-ag
2010-09-03 09:52:14,570 INFO  [STDOUT] (ClientSession Thread) Passivating SyncBean
2010-09-03 09:52:14,570 DEBUG [org.jboss.ejb3.cache.simple.StatefulSessionFilePersistenceManager] (ClientSession Thread) Saving session state to: E:\JBoss\jboss-5.1.0.GA_App_2.0\server\default\tmp\sessions\SyncBean-gdm5eriw-9x\5c4o03y-jjwh8j-gdm5d5bw-1-gdm5hy30-ag.ser
2010-09-03 09:52:14,574 DEBUG [org.jboss.ejb3.cache.simple.StatefulSessionFilePersistenceManager] (ClientSession Thread) Passivation complete; id=5c4o03y-jjwh8j-gdm5d5bw-1-gdm5hy30-ag

Has anyone come across this behaviour before?

Regards,

Greg

1. Re: SessionSyncronization and passivation

gthorburn Sep 20, 2010 6:51 PM (in response to gthorburn)

I have been digging a bit deeper into the problem when I had a bit of spare time, and after stepping through the passivation process to gain a better understanding of whats going on I came across the following method in SimpleStatefulCache:SessionTimeoutTask, run() method (Line 253 onwards, JBoss 5.1.0):

if (!running) return;
 
  boolean trace = log.isTraceEnabled();
  Iterator<Entry<Object, StatefulBeanContext>> it = cacheMap.entrySet().iterator();
  long now = System.currentTimeMillis();
  while (it.hasNext())
  {
     Entry<Object, StatefulBeanContext> entry = it.next();
     StatefulBeanContext centry = entry.getValue();
     if (now - centry.lastUsed >= sessionTimeout * 1000)
     {
        synchronized (centry)
        {                     
           if (centry.getCanPassivate())
           {
              if (!centry.getCanRemoveFromCache())
              {
                 passivationQueue.add(centry);
              }
              else if (trace)
              {
                 log.trace("Removing " + entry.getKey() + " from cache");
              }
           }
           else
           {
              centry.markedForPassivation = true;                              
              assert centry.isInUse() : centry + " is not in use, and thus will never be passivated";
           }
           // its ok to evict because it will be passivated
           // or we determined above that we can remove it
           it.remove();
        }
     }
     else if (trace)
     {
        log.trace("Not passivating; id=" + centry.getId() +
              " only inactive " + Math.max(0, now - centry.lastUsed) + " ms");
     }
  }

The 'centry.getCanPassivate()' in my case returns false, because the StatefulBeanContext has correctly flagged the bean as inUse. This still results in the StatefulBeanContext being removed from the cache, and it is not added to the passivation queue.

When the later lookup in the cache fails (its been removed), lookup in the passivationQueue also fails (it was not added), and the StatefulSessionFilePersistenceManager cannot find it in the file system, we end up with a NoSuchEJBException being thrown.

My understanding of the internal behaviour of JBoss is limited to stepping through the code a handful of times so I may be missing something, but shouldnt the bean remain in the cache (or at least be still accessible) if its still in use?