5 Replies Latest reply on Dec 7, 2008 11:15 PM by timfox

    JBoss Messaging IllegalMonitorStateException

    burnison Jun 9, 2008 5:39 PM

      Hello,

      I am experiencing several unexpected exceptions with JBoss. Though I am confident parts of these exceptions are attributed to JBoss Messaging, I am not sure if they are the cause or result. Unfortunately, I cannot find any similar problems or solutions therein.

      I am using Postgres 8.2 for the default, local-tx datasource, with a type-4 JDBC3 driver (though, I've also tried JDBC4). The JBoss Messaging persistence datasource is configured with the sample provided in the docs directory. I see this error with both JBoss 4.2.2 and JBoss EAP running on Fedora 8, 2.6.24 (with both vanilla and Fedora kernels), and Ubuntu, kernel 2.6.22, with the Sun 32-bit JVM (1.5.14 on Fedora and 1.5.13 on Ubuntu).

      Unfortunately, I do not know what is causing these problems. All transactions are container-managed with the implicit transaction type, REQUIRED, and all queues are using a transacted session. The basic algorithm follows (using EJB3):


      2. Local stateless session bean, Stateless-A, creates several entity beans, Set<Entity-A>.

      3. Stateless-A populates the instance fields of each Entity-A in Stateless-A::Set<Entity-A>, and then pushes each unpersisted Entity-A as an ObjectMessage, into a durable queue, Queue-A.

      4. Queue-A always receives each unpersisted Entity-A and successfully persists each one by making a call to a local stateless session bean, Stateless-B, which returns the persisted version of Entity-A, using EntityManager::merge(Object).

      5. Queue-A passes each persisted Entity-A::id (primitive long) (I have also tried passing Entity-A in an ObjectMessage) into another durable queue, Queue-B.


        At some point during or after step 3, and under what I consider is a light load (~50 messages in Stateless-A::Set<Entity-A>), I receive the following exception, randomly, and typically not for the same item in a constant dataset:

        2008-06-09 13:34:56,538 ERROR [org.jboss.resource.adapter.jms.inflow.JmsServerSession] org.jboss.resource.adapter.jms.inflow.JmsServerSession@98cf4d failed to commit/rollback
 at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1394)
 at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:135)
 at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:87)
 at org.jboss.resource.adapter.jms.inflow.JmsServerSession.run(JmsServerSession.java:248)
 at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:204)
 at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:275)
 at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:761)
 at java.lang.Thread.run(Thread.java:595)

2008-06-09 13:34:56,570 WARN [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.resources.arjunacore.preparefailed] [com.arjuna.ats.internal.jta.resources.arjunacore.preparefailed] XAResourceRecord.prepare - prepare failed with exception java.lang.IllegalMonitorStateException

2008-06-09 13:34:56,570 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_36] - BasicAction.End() - prepare phase of action-id 7f000001:87fd:484d6961:84c failed.

2008-06-09 13:34:56,570 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_38] - Action Aborting



        On a seeming-random basis (2 times in the last 2 weeks), I've also received the following stack trace shortly after the previous:

        2008-06-09 13:34:55,666 ERROR [STDERR] java.lang.IllegalMonitorStateException
 at java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(ReentrantLock.java:125)
 at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1137)
 at java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.java:431)
 at org.jboss.resource.adapter.jms.JmsManagedConnection.unlock(JmsManagedConnection.java:401)
 at org.jboss.resource.adapter.jms.JmsXAResource.end(JmsXAResource.java:76)
 at org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper.end(JcaXAResourceWrapper.java:58)
 at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:387)
 at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3222)
 at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3200)
 at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Abort(BasicAction.java:2211)
 at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1809)
 at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:88)
 at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)
 at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1382)
 at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:135)
 at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:87)
 at org.jboss.resource.adapter.jms.inflow.JmsServerSession$XATransactionDemarcationStrategy.end(JmsServerSession.java:494)
 at org.jboss.resource.adapter.jms.inflow.JmsServerSession.run(JmsServerSession.java:248)
 at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:204)
 at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:275)
 at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:761)
 at java.lang.Thread.run(Thread.java:595)


        Subsequent to the above, I get the following log entries:

        2008-06-09 13:34:55,750 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_54] - Top-level abort of action 7f000001:87fd:484d6961:426 received TwoPhaseOutcome.FINISH_ERROR from <ClassName:RecordType.JTA_RECORD>

2008-06-09 13:34:55,755 ERROR [org.jboss.resource.adapter.jms.inflow.JmsServerSession] org.jboss.resource.adapter.jms.inflow.JmsServerSession@743bcc failed to commit/rollback
 at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1394)
 at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:135)
 at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:87)
 at org.jboss.resource.adapter.jms.inflow.JmsServerSession.run(JmsServerSession.java:248)
 at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:204)
 at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:275)
 at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:761)
 at java.lang.Thread.run(Thread.java:595)



        Followed with the constant, evenly-delayed log entries listed below (please note these warnings are NOT being caused by an unclean shutdown, but by the issue reported in this thread):

        2008-06-09 13:36:30,825 ERROR [STDERR] **recoveryModules [com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule@a0e9b9, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule@50aa73, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule@1e68f43]

2008-06-09 13:36:30,826 WARN [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] Could not find new XAResource to use for recovering non-serializable XAResource < 131075, 28, 26, 1-7f000001:87fd:484d6961:3ac7f000001:87fd:484d6961:3cc^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@ >



        Another seeming side-effect lies within the JMX queue MBean view. The DeliveringCount and MessageCount both stay above 0. Neither values decrement, even long after the redelivery period*attempts has passed (I left JBoss running for 72 hours, and the queues had a 20 minute redelivery window).

        I greatly appreciate any help you can provide.

        Best regards,

        Richard Burnison


      • 5231 Views
      • Tags: