Unique-Constraint »jbm_msg_pkey« exceptions in a clustered
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.
