[QPID-8387] [Broker-J] JDBC based message stores do not wait for asynchronous message removal threads to complete when store is being closed

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: qpid-java-broker-7.1.0, qpid-java-broker-7.1.1, qpid-java-broker-7.1.2, qpid-java-broker-7.1.3, qpid-java-broker-7.1.4, qpid-java-broker-7.1.5, qpid-java-broker-7.1.6
• Fix Version/s: qpid-java-broker-7.1.6
• Component/s: Broker-J
• Assignee: Alex Rudyy
• Reporter: Alex Rudyy
• Created: 29/Nov/19 16:52
• Updated: 19/Feb/20 10:35
• Resolved: 02/Dec/19 10:05

Description

The asynchronous message removal was added into JDBC based message stores (Derby and JDBC) in version 7.1.0 of Qpid Broker-J as part of QPID-8242. The message removal now happens asynchronously in internal threads of JDBC based message stores.

However, when store is closed, the closing functionality does not wait for the asynchronous message removal threads to complete. This issue causes several side effects:

• the messages scheduled for removal might not be removed due to the close of the VirtualHost. Though, it is not an issue, as Broker on restart deletes all orphaned messages
• the asynchronous removal might result in ServerScopedRuntimeException being thrown from the removal thread. At the moment, those ServerScopedRuntimeException are ignored, but the intention of ServerScopedRuntimeException is to halt the JVM, and, this does not happen
• The restart of VirtualHost in integration tests can hang due to issues with store recovery

The following exception can be thrown from the tests in PersistentMessagingTest when any of derby profiles is used

019-11-29 12:33:23,062 DEBUG [Broker-Config] o.a.q.s.m.AbstractConfiguredObject All children closed DerbyVirtualHostNodeImplWithAccessChecking : PersistentMessagingTest_transactedAcknowledgementPersistence
2019-11-29 12:33:23,070 ERROR [PersistentMessagingTest_transactedAcknowledgementPersistence-store-1] o.a.q.s.u.ServerScopedRuntimeException Error removing messages with ids [3] from database: Java exception: ': org.apache.derby.shared.common.error.ShutdownException'.
java.sql.SQLException: Java exception: ': org.apache.derby.shared.common.error.ShutdownException'.
	at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
	at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
	at org.apache.derby.impl.jdbc.Util.seeNextException(Unknown Source)
	at org.apache.derby.impl.jdbc.Util.javaException(Unknown Source)
	at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(Unknown Source)
	at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(Unknown Source)
	at org.apache.derby.impl.jdbc.EmbedConnection.handleException(Unknown Source)
	at org.apache.derby.impl.jdbc.EmbedConnection.close(Unknown Source)
	at org.apache.derby.impl.jdbc.EmbedConnection.close(Unknown Source)
	at org.apache.qpid.server.store.jdbc.AbstractJDBCMessageStore.removeMessages(AbstractJDBCMessageStore.java:505)
	at org.apache.qpid.server.store.jdbc.AbstractJDBCMessageStore.lambda$scheduleMessageRemoval$0(AbstractJDBCMessageStore.java:461)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.derby.iapi.error.StandardException: Java exception: ': org.apache.derby.shared.common.error.ShutdownException'.
	at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
	at org.apache.derby.impl.jdbc.SQLExceptionFactory.wrapArgsForTransportAcrossDRDA(Unknown Source)
	... 18 common frames omitted
Caused by: org.apache.derby.shared.common.error.ShutdownException: 
	at org.apache.derby.iapi.services.context.ContextManager.checkInterrupt(Unknown Source)
	at org.apache.derby.iapi.services.context.ContextManager.getContext(Unknown Source)
	at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.getStatementContext(Unknown Source)
	at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.doRollback(Unknown Source)
	at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.userRollback(Unknown Source)
	at org.apache.derby.impl.jdbc.TransactionResourceImpl.rollback(Unknown Source)
	... 11 common frames omitted
2019-11-29 12:33:24,673 INFO  [Broker-Config] q.m.c.close <<UNKNOWN>> [vh(/PersistentMessagingTest_transactedAcknowledgementPersistence)/ms(DerbyConfigurationStore)] CFG-1003 : Closed
2019-11-29 12:33:24,673 INFO  [main] o.a.q.t.u.EmbeddedBrokerPerClassAdminImpl Starting VirtualHostNode for restart

As minimum, the following changes need to be implemented

• ServerScopedRuntimeException thrown from async message removal threads should halt Broker JVM
• The message store close functionality should either wait for in-progress removal to complete, or, cancel removal tasks gracefully
• The issue with test hanging should be resolved