End-of life issues for Stateful Session Beans
helga.w. Apr 8, 2012 11:35 AMI am in the progress of migrating an application from jBoss 4.x to jBoss 7.1
One of the issues I am having is that I am unsure if stateful session beans are destroyed in an orderly fashion. Specifically, it seems to me that I can't access member variables from a method annotated with @PreDestroy.
This is the example that I have created to reproduce this:
I have a session bean with a livespan of 1 minute. When it is destroyed, it should do some cleanup (most notably I need to inform a remote API that some limited resources can be released).
I log the entry into the @PostDestroy method, but whenever I try to access a member variable (even just to log the value), nothing happens, and all further logs are not printed, so it looks like the cleanup thread just hangs.
On the client side I have some test code that creates the bean, sleeps for 2 minutes (to make sure the session bean is dead) and then try to access the (now assumed dead) session bean. I get a notification from jBoss "ERROR [org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:66)] (ajp --127.0.0.1-8009-4) JBAS014134: EJB Invocation failed on component TestBean for method public abstract Error com.acme.Test.getLastMessage(): javax.ejb.NoSuchEJBException: Could not find SFSB TestBean with {[-49, 41, -116, -64, 26, -7, 65, 92, -87, 58, 123, 91, -88, 4, -77, 55]}"
This happens even though the the method call is wrapped in a try/catch to handle NoSuchEJBException.
So the questions I have are the following
- What am I doing wrong? This worked fine in 4.2.x
- Should I assume that the bean is already dead in @PreDestroy? If so, when should I do my cleanup?
- Am I accumulating an army of zombie TestBeans, stuck between the world of the living and the dead?
- What is the meaning of the Stack dump EJB Invocation failed on component... Why is it logged even though I am handling this exception in my code?
I am using jBoss AS 7.1.1 (jboss-as-7.1.1.Final)
Here is the relevant code
The session bean
@Stateful
@TransactionManagement
@StatefulTimeout(unit = TimeUnit.MINUTES, value = 1)
public class TestBean implements Test, TestLocal
{
@PersistenceContext(unitName = "userPU")
private EntityManager emUser;
private static final Logger logger = Logger.getLogger(TapBean.class);
private UUID uuid;
private DateTime liveSince;
// other stuff
public TestBean()
{
logger.info ("Creating a new instance of Test");
uuid = UUID.randomUUID();
liveSince = new DateTime();
}
@PrePassivate
public void passivate()
{
logger.info("passivating");
// never called
}
@PreDestroy
public void destroy()
{
DateTime now = new DateTime();
logger.info("destroying "); // this I see
cleanup();
logger.info("destroy took " + new Duration(now, new DateTime())); // this is never logged
}
@Remove
public void remove()
{
logger.info("timeout");
// never called
}
public void cleanup()
{
logger.info("Passivating '" + uuid + "' after " + new Duration(liveSince, new DateTime()).getStandardMinutes()); // never logged
// notify remote API to release resources
}
The web side code:
Test mySFSB = (Test) session.getAttribute("Test");
Error error = null;
logger.info("sleeping");
Thread.sleep(2*60000L);
logger.info("done sleeping");
try
{
logger.info("About to get last message" );
error = mySFSB.getLastMessage();
logger.info("done getting last message" );
}
catch (NoSuchEJBException e)
{
logger.error("Caught NoSuchEJBException " + e.getMessage());
}
catch (Exception e)
{
logger.error("Got " + e.getMessage());
}
Here is a log:
13:53:50,834 INFO [com.acme.server.TestBean.<init>(TestBean.java:140)] (ajp--127.0.0.1-8009-4) Creating a new instance of Test
.... do some server stuff
13:54:06,731 INFO [com.acme.web.PageAction.execute(PageAction.java:266)] (ajp--127.0.0.1-8009-4) sleeping
13:54:55,740 INFO [com.acme.server.TestBean.destroy(TestBean.java:158)] (pool-19-thread-1) destroying
// notice lack of a log message from the method cleanup()
13:56:06,730 INFO [com.acme.web.PageAction.execute(PageAction.java:268)] (ajp--127.0.0.1-8009-4) done sleeping
13:58:50,243 INFO [com.acme.web.PageAction.execute(PageAction.java:271)] (ajp--127.0.0.1-8009-4) About to get last message
// Here we know mySFSB is dead, but we think we are handling this gracefully
// Annoying ERROR log from jBoss, the meaning of which is not clear
13:58:50,246 ERROR [org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:66)] (ajp--127.0.0.1-8009-4) JBAS014134: EJB Invocation failed on component TestBean for method public abstract com.acme.server.data.TestError com.acme.server.Test.getLastMessage(): javax.ejb.NoSuchEJBException: Could not find SFSB TestBean with {[-49, 41, -116, -64, 26, -7, 65, 92, -87, 58, 123, 91, -88, 4, -77, 55]}
at org.jboss.as.ejb3.component.stateful.StatefulComponentInstanceInterceptor.processInvocation(StatefulComponentInstanceInterceptor.java:62) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:228) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.requiresNew(CMTTxInterceptor.java:333) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:192) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.remote.EJBRemoteTransactionPropagatingInterceptor.processInvocation(EJBRemoteTransactionPropagatingInterceptor.java:80) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:32) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
.... more stack stuff removed
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:930) [jbossweb-7.0.13.Final.jar:]
at java.lang.Thread.run(Thread.java:680) [classes.jar:1.6.0_29]
// Exception NoSuchEJBException caught
13:58:50,389 ERROR [com.acme.web.PageAction.execute(PageAction.java:277)] (ajp--127.0.0.1-8009-4) Caught NoSuchEJBException Got Could not find SFSB TestBean with {[-49, 41, -116, -64, 26, -7, 65, 92, -87, 58, 123, 91, -88, 4, -77, 55]}