[jboss-user] [JBoss Messaging] - JBoss Messaging IllegalMonitorStateException

Burnison do-not-reply at jboss.com
Mon Jun 9 17:39:06 EDT 2008 

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):


  | *  Local stateless session bean, Stateless-A, creates several entity beans, Set<Entity-A>.
  | 
  | *  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.
  | 
  | *  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).
  | 
  | *  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 at 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 at 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 at a0e9b9, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule at 50aa73, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule at 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

View the original post : http://www.jboss.com/index.html?module=bb&op=viewtopic&p=4156847#4156847

Reply to the post : http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&p=4156847

More information about the jboss-user mailing list