Deadlock in JDBC on exception writing to the DB

[artnaseef]

The deadlock below was observed in ActiveMQ 5.16.7. Reviewing changes to the code involved between 5.16.7 and the latest on main as of today (2026-02-28), it appears this deadlock still exists in the latest sources on main.

Found one Java-level deadlock:
=============================
"ActiveMQ Transport: tcp:///xxx.xxx.xxx.1:47818@61616":
  waiting to lock monitor 0x00007fe0a004a168 (object 0x00007fe1d44164c8, a java.util.LinkedList),
  which is held by "ActiveMQ Transport: tcp:///xxx.xxx.xxx.2:59618@61616"
"ActiveMQ Transport: tcp:///xxx.xxx.xxx.2:59618@61616":
  waiting to lock monitor 0x00007fe1908c7d68 (object 0x00007fe1d5107548, a java.util.LinkedList),
  which is held by "ActiveMQ Transport: tcp:///xxx.xxx.xxx.3:40762@61616"
"ActiveMQ Transport: tcp:///xxx.xxx.xxx.3:40762@61616":
  waiting to lock monitor 0x00007fe0a004a168 (object 0x00007fe1d44164c8, a java.util.LinkedList),
  which is held by "ActiveMQ Transport: tcp:///xxx.xxx.xxx.2:59618@61616"

Java stack information for the threads listed above:
===================================================
"ActiveMQ Transport: tcp:///xxx.xxx.xxx.1:47818@61616":
	at org.apache.activemq.store.jdbc.JDBCMessageStore.addMessage(JDBCMessageStore.java:131)
	- waiting to lock <0x00007fe1d44164c8> (a java.util.LinkedList)
	at org.apache.activemq.store.memory.MemoryTransactionStore.addMessage(MemoryTransactionStore.java:362)
	at org.apache.activemq.store.memory.MemoryTransactionStore$1.asyncAddQueueMessage(MemoryTransactionStore.java:161)
	at org.apache.activemq.broker.region.Queue.doMessageSend(Queue.java:885)
	at org.apache.activemq.broker.region.Queue.send(Queue.java:756)
	at org.apache.activemq.broker.region.AbstractRegion.send(AbstractRegion.java:511)
	at org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:477)
	at org.apache.activemq.broker.jmx.ManagedRegionBroker.send(ManagedRegionBroker.java:343)
	at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)
	at org.apache.activemq.broker.scheduler.SchedulerBroker.send(SchedulerBroker.java:320)
	at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)
	at org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:96)
	at org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:295)
	at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)
	at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)
	at org.apache.activemq.broker.TransportConnection.processMessage(TransportConnection.java:580)
	at org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:769)
	at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:335)
	at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:200)
	at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
	at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:125)
	at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:301)
	at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
	at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:233)
	at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:215)
	at java.lang.Thread.run(Thread.java:750)
"ActiveMQ Transport: tcp:///xxx.xxx.xxx.2:59618@61616":
	at org.apache.activemq.broker.region.Queue.onAdd(Queue.java:776)
	- waiting to lock <0x00007fe1d5107548> (a java.util.LinkedList)
	at org.apache.activemq.store.jdbc.JDBCMessageStore.addMessage(JDBCMessageStore.java:149)
	- locked <0x00007fe1d44164c8> (a java.util.LinkedList)
	at org.apache.activemq.store.memory.MemoryTransactionStore.addMessage(MemoryTransactionStore.java:362)
	at org.apache.activemq.store.memory.MemoryTransactionStore$1.asyncAddQueueMessage(MemoryTransactionStore.java:161)
	at org.apache.activemq.broker.region.Queue.doMessageSend(Queue.java:885)
	at org.apache.activemq.broker.region.Queue.send(Queue.java:756)
	at org.apache.activemq.broker.region.AbstractRegion.send(AbstractRegion.java:511)
	at org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:477)
	at org.apache.activemq.broker.jmx.ManagedRegionBroker.send(ManagedRegionBroker.java:343)
	at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)
	at org.apache.activemq.broker.scheduler.SchedulerBroker.send(SchedulerBroker.java:320)
	at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)
	at org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:96)
	at org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:295)
	at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)
	at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)
	at org.apache.activemq.broker.TransportConnection.processMessage(TransportConnection.java:580)
	at org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:769)
	at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:335)
	at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:200)
	at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
	at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:125)
	at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:301)
	at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
	at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:233)
	at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:215)
	at java.lang.Thread.run(Thread.java:750)
"ActiveMQ Transport: tcp:///xxx.xxx.xxx.3:40762@61616":
	at org.apache.activemq.store.jdbc.JDBCMessageStore$2.run(JDBCMessageStore.java:153)
	- waiting to lock <0x00007fe1d44164c8> (a java.util.LinkedList)
	at org.apache.activemq.broker.region.Queue.rollbackPendingCursorAdditions(Queue.java:788)
	- locked <0x00007fe1d5107548> (a java.util.LinkedList)
	at org.apache.activemq.broker.region.Queue.doMessageSend(Queue.java:895)
	at org.apache.activemq.broker.region.Queue.send(Queue.java:756)
	at org.apache.activemq.broker.region.AbstractRegion.send(AbstractRegion.java:511)
	at org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:477)
	at org.apache.activemq.broker.jmx.ManagedRegionBroker.send(ManagedRegionBroker.java:343)
	at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)
	at org.apache.activemq.broker.scheduler.SchedulerBroker.send(SchedulerBroker.java:320)
	at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)
	at org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:96)
	at org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:295)
	at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)
	at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)
	at org.apache.activemq.broker.TransportConnection.processMessage(TransportConnection.java:580)
	at org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:769)
	at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:335)
	at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:200)
	at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
	at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:125)
	at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:301)
	at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
	at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:233)
	at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:215)
	at java.lang.Thread.run(Thread.java:750)

Found 1 deadlock.

These are the key code snippets invovled:

org.apache.activemq.store.jdbc.JDBCMessageStore#addMessage
        synchronized (pendingAdditions) { pendingAdditions.remove(sequence); }

org.apache.activemq.broker.region.Queue#rollbackPendingCursorAdditions
        synchronized (indexOrderedCursorUpdates) {

There are 2 locks being acquired in different orders by 2 threads.

The lead-up is an exception thrown by store.addMessage, and the catch clause then calls rollbackPendingCursorAdditions on the queue.

Here is the full log of the offending exception:

WARN | Error while closing connection: IO Error: Connection timed out, due to: IO Error: Connection timed out
java.sql.SQLRecoverableException: IO Error: Connection timed out
	at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:993)
	at oracle.jdbc.driver.OraclePreparedStatement.executeForRowsWithTimeout(OraclePreparedStatement.java:9482)
	at oracle.jdbc.driver.OraclePreparedStatement.executeLargeBatch(OraclePreparedStatement.java:9586)
	at oracle.jdbc.driver.T4CPreparedStatement.executeLargeBatch(T4CPreparedStatement.java:1447)
	at oracle.jdbc.driver.OraclePreparedStatement.executeBatch(OraclePreparedStatement.java:9517)
	at oracle.jdbc.driver.OracleStatementWrapper.executeBatch(OracleStatementWrapper.java:237)
	at org.apache.commons.dbcp2.DelegatingStatement.executeBatch(DelegatingStatement.java:241)
	at org.apache.commons.dbcp2.DelegatingStatement.executeBatch(DelegatingStatement.java:241)
	at org.apache.commons.dbcp2.DelegatingStatement.executeBatch(DelegatingStatement.java:241)
	at org.apache.activemq.store.jdbc.TransactionContext.executeBatch(TransactionContext.java:138)
	at org.apache.activemq.store.jdbc.TransactionContext.executeBatch(TransactionContext.java:116)
	at org.apache.activemq.store.jdbc.TransactionContext.close(TransactionContext.java:169)
	at org.apache.activemq.store.jdbc.JDBCMessageStore.addMessage(JDBCMessageStore.java:168)
	at org.apache.activemq.store.memory.MemoryTransactionStore.addMessage(MemoryTransactionStore.java:362)
	at org.apache.activemq.store.memory.MemoryTransactionStore$1.asyncAddQueueMessage(MemoryTransactionStore.java:161)
	at org.apache.activemq.broker.region.Queue.doMessageSend(Queue.java:885)
	at org.apache.activemq.broker.region.Queue.send(Queue.java:756)
	at org.apache.activemq.broker.region.AbstractRegion.send(AbstractRegion.java:511)
	at org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:477)
	at org.apache.activemq.broker.jmx.ManagedRegionBroker.send(ManagedRegionBroker.java:343)
	at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)
	at org.apache.activemq.broker.scheduler.SchedulerBroker.send(SchedulerBroker.java:320)
	at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)
	at org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:96)
	at org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:295)
	at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)
	at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:154)
	at org.apache.activemq.broker.TransportConnection.processMessage(TransportConnection.java:580)
	at org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:769)
	at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:335)
	at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:200)
	at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
	at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:125)
	at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:301)
	at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
	at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:233)
	at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:215)
	at java.lang.Thread.run(Thread.java:750)

Note that I created a modified version of the code to reliably reproduce the problem in local testing. That test code can be seen on branch asn-debug-jdbc-slow-exception on my github fork of the project: artnaseef@e83f060

[artnaseef]

Also note that the exception handling on the DB failure does not end up logged because the catch clause re-throws the exception, but only AFTER the point that the deadlock occurs.

(UPDATE: on further review of my notes, this may not be correct - the exception may be logged elsewhere; needs verification)

[remay]

Also note that the exception handling on the DB failure does not end up logged because the catch clause re-throws the exception, but only AFTER the point that the deadlock occurs.

(UPDATE: on further review of my notes, this may not be correct - the exception may be logged elsewhere; needs verification)

@artnaseef In this particular case the IO Exception was logged (~15 minutes == tcp timeout + small amount after the TCP issue) and just before the deadlock occurred. I believe this is where it was logged within the JBDCMessageStore|::addMessage() method: https://github.com/apache/activemq/blob/main/activemq-jdbc-store/src/main/java/org/apache/activemq/store/jdbc/JDBCMessageStore.java#L165 But I agree with you that other errors might not be logged if they triggered the same deadlock.

[artnaseef]

@artnaseef In this particular case the IO Exception was logged (~15 minutes == tcp timeout + small amount after the TCP issue) and just before the deadlock occurred. I believe this is where it was logged within the JBDCMessageStore|::addMessage() method: https://github.com/apache/activemq/blob/main/activemq-jdbc-store/src/main/java/org/apache/activemq/store/jdbc/JDBCMessageStore.java#L165 But I agree with you that other errors might not be logged if they triggered the same deadlock.

Thank you @remay

I believe that getting the deadlock eliminated should make the logging of that exception at that point in the code a non-issue. The cleanup work being done should be fast and light.

[jeanouii]

Hi @artnaseef

Thank you for reporting the issue.
I'll take a look today or tomorrow if possible and let you know what I can find.

[jeanouii]

@artnaseef I looked a bit deeper in this and it looks like a real bug (deadlock). The short fix would be to take the runnable execution outside the critical section. There is really no reason to hold the lock till the end of the runnable execution.

Now, I need to look at a way to reproduce before fixing.

[artnaseef]

@jeanouii thanks for looking into it. The deadlock report I provided is from a broker running in production. If you look at the asn-debug-jdbc-slow-exception branch on my fork of the project, you'll see I added code to make reproducing the problem easy.

The underlying cause is an exception thrown by the persistence adapter, which is hard to reproduce.

I agree that running the cleanup on a separate thread could be an easy fix. Another possibility is to decide which order of acquiring the 2 locks is correct and make sure the second lock always happens only after the first one has been acquired.

I do wonder why the critical section is needed for the two lists - perhaps there's a simpler fix there?

[artnaseef]

Looking at it again now, perhaps this code snippet should just be moved after the critical section?

                if (indexListener != null) {
                    indexListener.onAdd(new IndexListener.MessageContext(context, message, new Runnable() {
                        @Override
                        public void run() {
                            // cursor add complete
                            synchronized (pendingAdditions) { pendingAdditions.remove(sequence); }
                        }
                    }));
                } else {

That's in org.apache.activemq.store.jdbc.JDBCMessageStore#addMessage.

I don'e see anything happening in that section of code that requires the lock on pendingAdditions when it executes. Note that I'm not talking about the callback inner synchronized - that part is fine.

[artnaseef]

Alternatively, or perhaps together, the mc.completion.run() below could be moved outside of the critical section as well (this one would require a little more work because of the loop):

    public void rollbackPendingCursorAdditions(MessageId messageId) {
        synchronized (indexOrderedCursorUpdates) {
            for (int i = indexOrderedCursorUpdates.size() - 1; i >= 0; i--) {
                MessageContext mc = indexOrderedCursorUpdates.get(i);
                if (mc.message.getMessageId().equals(messageId)) {
                    indexOrderedCursorUpdates.remove(mc);
                    if (mc.onCompletion != null) {
                        mc.onCompletion.run();
                    }
                    break;
                }
            }
        }
    }

That's org.apache.activemq.broker.region.Queue#rollbackPendingCursorAdditions

[jeanouii]

The choice I made is the last one. Moving the onCompletion.run() outside the critical section.
I'm working on the test. Should be done by tomorrow and then I'll see with the team if we can backport and to which branch