TransactionReaper not respecting timeout?
hipjon Jul 14, 2010 3:36 PMI started having an issue with my application under JBoss 6 where some transactions are dieing, seemingly at random. The TransactionReaper appears to be kicking in extremely early. I have not isolated the cause of the issue, but it seems to have started since I added code to my app that calls a SLSB with the TRANSACTION_NEW attribute.
I have created the following test code. Success or failure is unpredictable.
TestResource is a simple JAX-RS/Resteasy class that accesses the TransactionManager, begins a transaction, and sets a long timeout. It then calls a SLSB with TRANSACTION_NEW and sleeps for a while.
@Path("/test") public class TestResource { static Logger log = Logger.getLogger(TestResource.class); @GET @Path("/timetest2") @Produces("text/plain") public void timeTest2() throws Exception { TransactionManager tmgr = (TransactionManager)new InitialContext().lookup("java:/TransactionManager"); tmgr.begin(); tmgr.setTransactionTimeout(30*60); // 30 minute timeout Transaction tx = tmgr.getTransaction(); log.info("Started tx: " + tx.toString()); TestBean bean = (TestBean)(new InitialContext().lookup("TestBean/no-interface")); bean.sleep(5*1000); // sleep 5 seconds Thread.sleep(30*1000); // sleep 30 seconds log.info("before commit, tx = " + tx.toString()); tx.commit(); log.info("after commit, tx = " + tx.toString()); } }
Here's the SLSB with TRANSACTION_NEW.
@Stateless(name="TestBean") public class TestBean { @TransactionAttribute(TransactionAttributeType.REQUIRES_NEW) public void sleep(int time) throws Exception { Thread.sleep(time); } }
Sometimes the timetest2 method executes and commits the TX without a problem. Sometimes the TransactionReaper kicks in early and the commit fails. Here is the log output of the failure scenario.
2010-07-14 15:19:44,958 INFO [edu.harvard.hul.ois.drs2.services.rest.TestResour
ce] (http-0.0.0.0-18280-2) Started tx: TransactionImple < ac, BasicAction: 0:fff
f8067e513:3a42:4c3e07af:6c status: ActionStatus.RUNNING >
2010-07-14 15:19:49,958 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (Thr
ead-9) [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionRea
per::check timeout for TX 0:ffff8067e513:3a42:4c3e07af:6c in state RUN
2010-07-14 15:19:49,959 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (Thr
ead-10) [com.arjuna.ats.arjuna.coordinator.TransactionReaper_7] - TransactionRea
per::doCancellations worker Thread[Thread-10,5,jboss] successfully canceled TX 0
:ffff8067e513:3a42:4c3e07af:6c
2010-07-14 15:20:19,961 INFO [edu.harvard.hul.ois.drs2.services.rest.TestResour
ce] (http-0.0.0.0-18280-2) before commit, tx = TransactionImple < ac, BasicActio
n: 0:ffff8067e513:3a42:4c3e07af:6c status: ActionStatus.ABORTED >
2010-07-14 15:20:19,961 ERROR [org.apache.catalina.core.ContainerBase.[jboss.web
].[localhost].[/drs].[Resteasy]] (http-0.0.0.0-18280-2) Servlet.service() for se
rvlet Resteasy threw exception: org.jboss.resteasy.spi.UnhandledException: java.
lang.IllegalStateException: [com.arjuna.ats.internal.jta.transaction.arjunacore.
inactive] [com.arjuna.ats.internal.jta.transaction.arjunacore.inactive] The tran
saction is not active!
...snip
2010-07-14 15:20:19,963 ERROR [org.jboss.web.tomcat.service.jca.CachedConnection
Valve] (http-0.0.0.0-18280-2) Application error: Resteasy did not complete its t
ransaction suspended tx=TransactionImple < ac, BasicAction: 0:ffff8067e513:3a42:
4c3e07af:6c status: ActionStatus.ABORTED >
You can see that the TransactionReaper kicks off just seconds after the TX is created. Is this possibly a bug with calling an EJB with TRANSACTION_NEW?
Thanks,
Jon