0 Replies Latest reply on May 14, 2012 3:15 AM by ukriegel

Timeout-Error for TimerBean after 1 hour runtime

ukriegel May 14, 2012 3:15 AM

Hi there,

we deployed a timer bean on Jboss6.1.0.final, which sends every 10 secs a short text message into a topic. After approximately a runtime of 1 hour,

the following error occurs

ERROR [org.jboss.ejb3.timerservice.mk2.task.TimerTask] (pool-16-thread-8) Error invoking timeout for timer: [id=166282d0-24a8-472c-a8fb-2c9acaafb24b timedObjectId=jboss.j2ee:jar=heartbeat-1.0.1.jar,name=LifeSignSingleton,service=EJB3 auto-timer?:true persistent?:false timerService=org.jboss.ejb3.timerservice.mk2.TimerServiceImpl@6ac72423 initialExpiration=Fri May 11 00:00:00 CEST 2012 intervalDuration(in milli sec)=0 nextExpiration=Fri May 11 14:21:20 CEST 2012 timerState=IN_TIMEOUT: javax.ejb.EJBTransactionRolledbackException: Transaction rolled back

at org.jboss.ejb3.tx2.impl.CMTTxInterceptor.handleEndTransactionException(CMTTxInterceptor.java:115) [:0.0.2]

at org.jboss.ejb3.tx2.impl.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:87) [:0.0.2]

at org.jboss.ejb3.tx2.impl.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:255) [:0.0.2]

at org.jboss.ejb3.tx2.impl.CMTTxInterceptor.required(CMTTxInterceptor.java:349) [:0.0.2]

at org.jboss.ejb3.tx2.impl.CMTTxInterceptor.invoke(CMTTxInterceptor.java:209) [:0.0.2]

at org.jboss.ejb3.tx2.aop.CMTTxInterceptorWrapper.invoke(CMTTxInterceptorWrapper.java:52) [:0.0.2]

at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) [jboss-aop.jar:2.2.2.GA]

at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:76) [:1.0.0.GA]

at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) [jboss-aop.jar:2.2.2.GA]

at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:41) [:1.7.21]

at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) [jboss-aop.jar:2.2.2.GA]

at org.jboss.ejb3.BlockContainerShutdownInterceptor.invoke(BlockContainerShutdownInterceptor.java:67) [:1.7.21]

at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) [jboss-aop.jar:2.2.2.GA]

at org.jboss.ejb3.core.context.CurrentInvocationContextInterceptor.invoke(CurrentInvocationContextInterceptor.java:47) [:1.7.21]

at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) [jboss-aop.jar:2.2.2.GA]

at org.jboss.aspects.currentinvocation.CurrentInvocationInterceptor.invoke(CurrentInvocationInterceptor.java:67) [:1.0.1]

at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) [jboss-aop.jar:2.2.2.GA]

at org.jboss.ejb3.interceptor.EJB3TCCLInterceptor.invoke(EJB3TCCLInterceptor.java:86) [:1.7.21]

at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) [jboss-aop.jar:2.2.2.GA]

at org.jboss.ejb3.singleton.aop.impl.AOPBasedInterceptorRegistry.intercept(AOPBasedInterceptorRegistry.java:111) [:1.0.2]

at org.jboss.ejb3.singleton.impl.container.SingletonContainer.invoke(SingletonContainer.java:206) [:1.0.2]

at org.jboss.ejb3.singleton.aop.impl.AOPBasedSingletonContainer.callTimeout(AOPBasedSingletonContainer.java:888) [:1.0.2]

at org.jboss.ejb3.timerservice.mk2.task.CalendarTimerTask.callTimeout(CalendarTimerTask.java:80) [:1.0.0-alpha-13]

at org.jboss.ejb3.timerservice.mk2.task.TimerTask.run(TimerTask.java:127) [:1.0.0-alpha-13]

at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441) [:1.6.0_29]

at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) [:1.6.0_29]

at java.util.concurrent.FutureTask.run(FutureTask.java:138) [:1.6.0_29]

at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:98) [:1.6.0_29]

at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:206) [:1.6.0_29]

at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [:1.6.0_29]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [:1.6.0_29]

at java.lang.Thread.run(Thread.java:680) [:1.6.0_29]

Caused by: javax.transaction.RollbackException: ARJUNA-16063 The transaction is not active!

at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1148) [:6.1.0.Final]

at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:119) [:6.1.0.Final]

at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75) [:6.1.0.Final]

at org.jboss.ejb3.tx2.impl.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:82) [:0.0.2]

... 30 more

The Bean doesn't recover from that error, which will occur every few seconds.

----------- Here is the code of the bean --------------

package foo;

import javax.annotation.Resource;

import javax.ejb.LocalBean;

import javax.ejb.Schedule;

import javax.ejb.Singleton;

import javax.ejb.Startup;

import javax.ejb.Timeout;

import javax.jms.Connection;

import javax.jms.ConnectionFactory;

import javax.jms.JMSException;

import javax.jms.MessageProducer;

import javax.jms.Session;

import javax.jms.TextMessage;

import javax.jms.Topic;

import org.apache.log4j.Logger;

@Singleton(name = "LifeSignSingleton", mappedName = "java:global/heartbeat/LifeSignSingleton")

@LocalBean

@Startup

public class LifeSignSingleton {

private static final Logger logger = Logger

.getLogger(LifeSignSingleton.class);

private static final String SUBJECT = "SUBJECT";

private static final String UNMARSHALLER = "UNMARSHALLER";

@Resource(mappedName="/ConnectionFactory")

private ConnectionFactory connectionFactory;

@Resource(mappedName="topic/Input")

private Topic topic;

/**

* Default constructor.

public LifeSignSingleton() {

}

@Timeout

@Schedule(second = "*/10", minute = "*", hour = "*", persistent = false)

public void timeout() {

send("foo", SUBJECT, UNMARSHALLER,"name", "passwd");

}

public void send(final String messageText, final String subject,

final String unmarshaller, String userName, String passwd) {

try {

Connection connection = connectionFactory.createConnection(userName, passwd);

logger.trace("connection: "+connection);

Session session = connection.createSession(false, Session.AUTO_ACKNOWLEDGE);

logger.trace("session: "+session);

MessageProducer publisher = session.createProducer(topic);

logger.trace("publisher: "+publisher);

final TextMessage message = session.createTextMessage(messageText);

message.setStringProperty("subject", subject);

message.setStringProperty("unmarshaller", unmarshaller);

logger.debug("textMessage: " + message.getText());

publisher.send(message);

connection.close();

} catch (JMSException e) {

logger.error("JMSException: ", e);

}

What's wrong with the implementation

We restarted our test and now it run 6 hours befor chras. However there are a few WARNs befor the ERROR.

2012-05-11 21:47:50,001 WARN [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA-12117 TransactionReaper::check timeout for TX 0:ffff0a16dd63:126a:4fad1016:bb28 in state RUN

2012-05-11 21:47:50,003 WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12095 Abort of action id 0:ffff0a16dd63:126a:4fad1016:bb28 invoked while multiple threads active within it.

2012-05-11 21:47:50,003 WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12108 CheckedAction::check - atomic action 0:ffff0a16dd63:126a:4fad1016:bb28 aborting with 1 threads active!

2012-05-11 21:47:50,004 WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12121 TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,jboss] successfully canceled TX 0:ffff0a16dd63:126a:4fad1016:bb28

2012-05-11 21:48:00,003 WARN [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA-12117 TransactionReaper::check timeout for TX 0:ffff0a16dd63:126a:4fad1016:bb3a in state RUN

2012-05-11 21:48:00,004 ERROR [org.jboss.ejb3.timerservice.mk2.task.TimerTask] (pool-16-thread-3) Error invoking timeout for timer: [id=70278bc3-a965-4e2e-be6f-87b9070b8fcf timedObjectId=jboss.j2ee:jar=heartbeat-1.0.1.jar,name=LifeSignSingleton,service=EJB3 auto-timer?:true persistent?:false timerService=org.jboss.ejb3.timerservice.mk2.TimerServiceImpl@3cf3aa19 initialExpiration=Fri May 11 00:00:00 CEST 2012 intervalDuration(in milli sec)=0 nextExpiration=Fri May 11 21:44:30 CEST 2012 timerState=IN_TIMEOUT: javax.ejb.ConcurrentAccessTimeoutException: EJB 3.1 PFD2 4.8.5.5.1 concurrent access timeout on [advisedMethod=public void de.fraunhofer.fokus.imsk.server.heartbeat.LifeSignSingleton.timeout(), unadvisedMethod=public void de.fraunhofer.fokus.imsk.server.heartbeat.LifeSignSingleton.timeout(), metadata=null, targetObject=de.fraunhofer.fokus.imsk.server.heartbeat.LifeSignSingleton@11fa8e8e, arguments=null] - could not obtain lock within 5MINUTES

at org.jboss.ejb3.concurrency.aop.interceptor.ContainerManagedConcurrencyInterceptor.invoke(ContainerManagedConcurrencyInterceptor.java:176) [:1.0.0-alpha-4]

at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:86) [jboss-aop.jar:2.2.2.GA]

at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) [jboss-aop.jar:2.2.2.GA]

at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47) [:1.7.21]

at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) [jboss-aop.jar:2.2.2.GA]

at org.jboss.ejb3.tx.NullInterceptor.invoke(NullInterceptor.java:42) [:1.0.4]

at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) [jboss-aop.jar:2.2.2.GA]

at org.jboss.ejb3.core.context.SessionInvocationContextAdapter.proceed(SessionInvocationContextAdapter.java:95) [:1.7.21]

at org.jboss.ejb3.tx2.impl.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:247) [:0.0.2]