6 Replies Latest reply on Jul 9, 2009 2:57 AM by Maurice Zeijen

    Unique-Constraint »jbm_msg_pkey« exceptions in a clustered

    Maurice Zeijen Master

      Yesterday I put a new system in production that uses a JBoss Messaging cluster. This is the first time that I put a JBoss Messaging cluster in production and now I am running into some exceptions that I am worry about. These messages didn't result in message loss until know but I don't know if it could result to message loss in the future.

      First the platform description:

      ESB Servers (2 nodes):
      Windows
      JBoss ESB server 4.5.GA (using JBoss 4.2.3.GA)
      JBoss Messaging 1.4.2.GA-SP1

      Database:
      Postgres 8.3.6

      First I get these warnings at one of the nodes:

      2009-06-10 09:21:11,712 WARN [org.jboss.messaging.core.impl.JDBCSupport] SQLException caught, SQLState 23505 code:0- assuming deadlock detected, try:1
      org.postgresql.util.PSQLException: FEHLER: doppelter Schlüsselwert verletzt Unique-Constraint »jbm_msg_pkey«
       at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:1592)
       at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1327)
       at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:192)
       at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:451)
       at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:350)
       at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:304)
       at org.jboss.resource.adapter.jdbc.CachedPreparedStatement.executeUpdate(CachedPreparedStatement.java:95)
       at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:365)
       at org.jboss.messaging.core.impl.JDBCPersistenceManager$1HandleBeforePrepareRunner.doTransaction(JDBCPersistenceManager.java:1992)
       at org.jboss.messaging.core.impl.JDBCSupport$JDBCTxRunner2.execute(JDBCSupport.java:474)
       at org.jboss.messaging.core.impl.JDBCSupport$JDBCTxRunner2.executeWithRetry(JDBCSupport.java:512)
       at org.jboss.messaging.core.impl.JDBCPersistenceManager.handleBeforePrepare(JDBCPersistenceManager.java:2063)
       at org.jboss.messaging.core.impl.JDBCPersistenceManager$TransactionCallback.beforePrepare(JDBCPersistenceManager.java:2984)
       at org.jboss.messaging.core.impl.tx.Transaction.prepare(Transaction.java:265)
       at org.jboss.jms.server.endpoint.ServerConnectionEndpoint.sendTransaction(ServerConnectionEndpoint.java:498)
       at org.jboss.jms.server.endpoint.advised.ConnectionAdvised.org$jboss$jms$server$endpoint$advised$ConnectionAdvised$sendTransaction$aop(ConnectionAdvised.java:101)
       at org.jboss.jms.server.endpoint.advised.ConnectionAdvised$sendTransaction_N3268650789275322226.invokeNext(ConnectionAdvised$sendTransaction_N3268650789275322226.java)
       at org.jboss.jms.server.container.SecurityAspect.handleSendTransaction(SecurityAspect.java:195)
       at sun.reflect.GeneratedMethodAccessor198.invoke(Unknown Source)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
       at java.lang.reflect.Method.invoke(Method.java:585)
       at org.jboss.aop.advice.PerInstanceAdvice.invoke(PerInstanceAdvice.java:121)
       at org.jboss.jms.server.endpoint.advised.ConnectionAdvised$sendTransaction_N3268650789275322226.invokeNext(ConnectionAdvised$sendTransaction_N3268650789275322226.java)
       at org.jboss.jms.server.container.ServerLogInterceptor.invoke(ServerLogInterceptor.java:105)
       at org.jboss.jms.server.endpoint.advised.ConnectionAdvised$sendTransaction_N3268650789275322226.invokeNext(ConnectionAdvised$sendTransaction_N3268650789275322226.java)
       at org.jboss.jms.server.endpoint.advised.ConnectionAdvised.sendTransaction(ConnectionAdvised.java)
       at org.jboss.jms.wireformat.ConnectionSendTransactionRequest.serverInvoke(ConnectionSendTransactionRequest.java:82)
       at org.jboss.jms.server.remoting.JMSServerInvocationHandler.invoke(JMSServerInvocationHandler.java:143)
       at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:866)
       at org.jboss.remoting.transport.local.LocalClientInvoker.invoke(LocalClientInvoker.java:101)
       at org.jboss.remoting.Client.invoke(Client.java:1634)
       at org.jboss.remoting.Client.invoke(Client.java:548)
       at org.jboss.remoting.Client.invoke(Client.java:536)
       at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:189)
       at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:160)
       at org.jboss.jms.client.delegate.ClientConnectionDelegate.org$jboss$jms$client$delegate$ClientConnectionDelegate$sendTransaction$aop(ClientConnectionDelegate.java:221)
       at org.jboss.jms.client.delegate.ClientConnectionDelegate$sendTransaction_N3268650789275322226.invokeNext(ClientConnectionDelegate$sendTransaction_N3268650789275322226.java)
       at org.jboss.jms.client.container.FailoverValveInterceptor.invoke(FailoverValveInterceptor.java:92)
       at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
       at org.jboss.jms.client.delegate.ClientConnectionDelegate$sendTransaction_N3268650789275322226.invokeNext(ClientConnectionDelegate$sendTransaction_N3268650789275322226.java)
       at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170)
       at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
       at org.jboss.jms.client.delegate.ClientConnectionDelegate$sendTransaction_N3268650789275322226.invokeNext(ClientConnectionDelegate$sendTransaction_N3268650789275322226.java)
       at org.jboss.jms.client.delegate.ClientConnectionDelegate.sendTransaction(ClientConnectionDelegate.java)
       at org.jboss.jms.tx.ResourceManager.sendTransactionXA(ResourceManager.java:662)
       at org.jboss.jms.tx.ResourceManager.prepare(ResourceManager.java:337)
       at org.jboss.jms.tx.MessagingXAResource.prepare(MessagingXAResource.java:240)
       at org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper.prepare(JcaXAResourceWrapper.java:93)
       at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelPrepare(XAResourceRecord.java:264)
       at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2871)
       at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2828)
       at com.arjuna.ats.arjuna.coordinator.BasicAction.prepare(BasicAction.java:2382)
       at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1783)
       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:1389)
       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)
      
      


      The german exception (why localized exception messages... :( ) "doppelter Schlüsselwert verletzt Unique-Constraint" translates to "double keyvalue violates Unique-Constraint".

      After 25 of these messages I get the following error on the same node:

      2009-06-10 09:00:17,838 ERROR [org.jboss.messaging.core.impl.JDBCSupport] Retried 25 times, now giving up
      2009-06-10 09:00:17,838 ERROR [org.jboss.messaging.util.ExceptionUtil] ConnectionEndpoint[ai-p42wkrvf-1-76iy9rvf-8gbfr5-2aaa] sendTransaction [a68-ijfyorvf-1-76iy9rvf-8gbfr5-2aaa]
      java.lang.IllegalStateException: Failed to execute transaction
       at org.jboss.messaging.core.impl.JDBCSupport$JDBCTxRunner2.executeWithRetry(JDBCSupport.java:544)
       at org.jboss.messaging.core.impl.JDBCPersistenceManager.handleBeforePrepare(JDBCPersistenceManager.java:2063)
       at org.jboss.messaging.core.impl.JDBCPersistenceManager$TransactionCallback.beforePrepare(JDBCPersistenceManager.java:2984)
       at org.jboss.messaging.core.impl.tx.Transaction.prepare(Transaction.java:265)
       at org.jboss.jms.server.endpoint.ServerConnectionEndpoint.sendTransaction(ServerConnectionEndpoint.java:498)
       at org.jboss.jms.server.endpoint.advised.ConnectionAdvised.org$jboss$jms$server$endpoint$advised$ConnectionAdvised$sendTransaction$aop(ConnectionAdvised.java:101)
       at org.jboss.jms.server.endpoint.advised.ConnectionAdvised$sendTransaction_N3268650789275322226.invokeNext(ConnectionAdvised$sendTransaction_N3268650789275322226.java)
       at org.jboss.jms.server.container.SecurityAspect.handleSendTransaction(SecurityAspect.java:195)
       at sun.reflect.GeneratedMethodAccessor198.invoke(Unknown Source)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
       at java.lang.reflect.Method.invoke(Method.java:585)
       at org.jboss.aop.advice.PerInstanceAdvice.invoke(PerInstanceAdvice.java:121)
       at org.jboss.jms.server.endpoint.advised.ConnectionAdvised$sendTransaction_N3268650789275322226.invokeNext(ConnectionAdvised$sendTransaction_N3268650789275322226.java)
       at org.jboss.jms.server.container.ServerLogInterceptor.invoke(ServerLogInterceptor.java:105)
       at org.jboss.jms.server.endpoint.advised.ConnectionAdvised$sendTransaction_N3268650789275322226.invokeNext(ConnectionAdvised$sendTransaction_N3268650789275322226.java)
       at org.jboss.jms.server.endpoint.advised.ConnectionAdvised.sendTransaction(ConnectionAdvised.java)
       at org.jboss.jms.wireformat.ConnectionSendTransactionRequest.serverInvoke(ConnectionSendTransactionRequest.java:82)
       at org.jboss.jms.server.remoting.JMSServerInvocationHandler.invoke(JMSServerInvocationHandler.java:143)
       at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:866)
       at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:608)
       at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:420)
       at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:173)
      


      On the other node I get this message around the same time and I guess that they are related to each other:

      2009-06-10 09:00:17,307 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 XAException.XA_RETRY
      2009-06-10 09:00:17,307 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_36] - BasicAction.End() - prepare phase of action-id a0a0a01:420:4a2f0671:b60c failed.
      2009-06-10 09:00:17,307 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_38] - Action Aborting
      2009-06-10 09:00:17,307 ERROR [org.jboss.resource.adapter.jms.inflow.JmsServerSession] org.jboss.resource.adapter.jms.inflow.JmsServerSession@61befe failed to commit/rollback
      javax.transaction.RollbackException: [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] Can't commit because the transaction is in aborted state
       at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1401)
       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)
      2009-06-10 09:00:17,885 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 XAException.XA_RETRY
      2009-06-10 09:00:17,885 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_36] - BasicAction.End() - prepare phase of action-id a0a0a01:420:4a2f0671:b5f9 failed.
      2009-06-10 09:00:17,885 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_38] - Action Aborting
      2009-06-10 09:00:17,900 ERROR [org.jboss.resource.adapter.jms.inflow.JmsServerSession] org.jboss.resource.adapter.jms.inflow.JmsServerSession@11608a4 failed to commit/rollback
      javax.transaction.RollbackException: [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] Can't commit because the transaction is in aborted state
       at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1401)
       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)
      


      Do I need to worry about these log messages? And if I do then what can I do about it?

      Thanks for your help.