0 Replies Latest reply: May 14, 2012 3:15 AM by Ulrich Kriegel RSS

    Timeout-Error for TimerBean after 1 hour runtime

    Ulrich Kriegel Newbie

      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]

                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]

       

      Any hints to resolve that problem are welcome

       

      Nachricht geändert durch Ulrich Kriegel