Details
-
Bug
-
Resolution: Not a Bug
-
Major
-
None
-
JBoss A-MQ 6.3
-
None
Description
We have a JDBC master/slave setup. We saw a strange behaviour that failover to slave broker failed due to the error "java.sql.SQLIntegrityConstraintViolationException: ORA-00001: unique constraint (ESB.SYS_C007328) violated".
Here are logs showing what happened:
2019-09-08 01:02:13,851 | DEBUG | AMQ-1-thread-1 | LeaseDatabaseLocker | q.store.jdbc.LeaseDatabaseLocker 101 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630377 | broker01 failed to acquire lease. Sleeping for 20000 milli(s) before trying again...
2019-09-08 01:02:33,854 | DEBUG | AMQ-1-thread-1 | LeaseDatabaseLocker | q.store.jdbc.LeaseDatabaseLocker 183 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630377 | broker01, lease keepAlive Query is UPDATE ACTIVEMQ_LOCK SET BROKER_NAME=?, TIME=? WHERE BROKER_NAME=? AND ID = 1
2019-09-08 01:02:33,860 | INFO | AMQ-1-thread-1 | LeaseDatabaseLocker | q.store.jdbc.LeaseDatabaseLocker 108 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630377 | broker01, becoming master with lease expiry Sun Sep 08 01:02:53 UTC 2019 on dataSource: org.apache.commons.dbcp.BasicDataSource@524075fb
2019-09-08 01:02:33,875 | INFO | AMQ-1-thread-1 | PListStoreImpl | tore.kahadb.plist.PListStoreImpl 345 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630377 | PListStore:[/opt/apache-activemq/data/broker01/tmp_storage] started
2019-09-08 01:02:33,876 | DEBUG | A Scheduled Task | JDBCPersistenceAdapter | tore.jdbc.JDBCPersistenceAdapter 366 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630377 | Cleaning up old messages.
2019-09-08 01:02:33,879 | DEBUG | A Scheduled Task | DefaultJDBCAdapter | .jdbc.adapter.DefaultJDBCAdapter 804 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630377 | Executing SQL: DELETE FROM ACTIVEMQ_MSGS WHERE (PRIORITY=? AND ID <= ( SELECT min(ACTIVEMQ_ACKS.LAST_ACKED_ID) FROM ACTIVEMQ_ACKS WHERE ACTIVEMQ_ACKS.CONTAINER=ACTIVEMQ_MSGS.CONTAINER AND ACTIVEMQ_ACKS.PRIORITY=?) )
2019-09-08 01:02:33,897 | DEBUG | A Scheduled Task | DefaultJDBCAdapter | .jdbc.adapter.DefaultJDBCAdapter 810 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630377 | Deleted 0 old message(s) at priority: 0
2019-09-08 01:02:33,897 | DEBUG | A Scheduled Task | JDBCPersistenceAdapter | tore.jdbc.JDBCPersistenceAdapter 382 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630377 | Cleanup done.
2019-09-08 01:02:34,339 | WARN | AMQ-1-thread-1 | JDBCPersistenceAdapter | tore.jdbc.JDBCPersistenceAdapter 286 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630377 | Broker sequence id wasn't recovered properly, possible duplicates!
2019-09-08 01:02:34,875 | DEBUG | A Scheduled Task | LeaseDatabaseLocker | q.store.jdbc.LeaseDatabaseLocker 183 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630377 | broker01, lease keepAlive Query is UPDATE ACTIVEMQ_LOCK SET BROKER_NAME=?, TIME=? WHERE BROKER_NAME=? AND ID = 1
...
...
2019-09-08 01:02:45,383 | INFO | AMQ-1-thread-1 | ActiveMQServiceFactory | ceFactory$ClusteredConfiguration 557 | 176 - io.fabric8.mq.mq-fabric - 1.2.0.redhat-630377 | Broker amq has started.
2019-09-08 01:02:45,875 | DEBUG | A Scheduled Task | LeaseDatabaseLocker | q.store.jdbc.LeaseDatabaseLocker 183 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630377 | broker01, lease keepAlive Query is UPDATE ACTIVEMQ_LOCK SET BROKER_NAME=?, TIME=? WHERE BROKER_NAME=? AND ID = 1
...
...
2019-09-08 01:02:49,719 | WARN | .208:45506@14016 | JDBCPersistenceAdapter | tore.jdbc.JDBCPersistenceAdapter 628 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630377 | Commit failed: ORA-00001: unique constraint (ESB.SYS_C007328) violatedn | , due to: ORA-00001: unique constraint (ESB.SYS_C007328) violatedn |
java.sql.SQLIntegrityConstraintViolationException: ORA-00001: unique constraint (ESB.SYS_C007328) violated
at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:450)[ojdbc7-12.1.0.2.0.jar:12.1.0.2.0]
at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:399)[ojdbc7-12.1.0.2.0.jar:12.1.0.2.0]
at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:1059)[ojdbc7-12.1.0.2.0.jar:12.1.0.2.0]
The slave broker above took over and became master after the master broker failed. But only after 5 seconds, this broker failed again due to the error "java.sql.SQLIntegrityConstraintViolationException: ORA-00001: unique constraint (ESB.SYS_C007328) violated".
By checking scheme on the backend Oracle Database, the constraint name "ESB.SYS_C007328" was associated with the ACTIVEMQ_MSG table and it would indicate that broker was trying to insert the record a second time, resulting in a primary key constraint violation.
However, even with DEBUG level logging on the logger "org.apache.activemq.store.jdbc" was enabled, we still did not see any queries for ACTIVEMQ_MSG table, although we only saw queries for ACTIVEMQ_LOCK table for updating LeaseDatabaseLocker.
