Transaction manager-related backports and fixes #35242
Merged
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
(cherry picked from commit fd02a43)
Until now, we were using some transformed data, which wasn't very practical when we needed more information. (cherry picked from commit 6e44d77)
(cherry picked from commit c3ae13e)
(cherry picked from commit d99f0b5)
This is a band aid, really and I think we will need to take a step back and rethink how all this is started and shut down.
|
I tested this with the quickstart and QE tests that I am preparing - this PR fixes my issues. I am yet to cover hot reload / dev services and other more complex scenarios, but for what I am able to test right now, works. Thank you |
|
hmm, just one thing, when I add a new java file (I actually added StartupService mentioned in quickstart PR) in DEV Mode and force restart with but whatever it means, I am still happy that recovery works with this PR, thanks. UPDATE: after the forced restart, this exception keeps to be logged in |
|
Is it the full stacktrace? |
That's all I can see without adjusting loggin in DEV mode. I actually don't use DEV mode that much, but I'll check if it is possible to change logging and I'll also try to write down exact steps how to reproduce it (c & p). |
|
Reproducer:
//package org.acme.quickstart;
//
//import io.agroal.api.AgroalDataSource;
//import io.quarkus.runtime.StartupEvent;
//import jakarta.enterprise.context.ApplicationScoped;
//import jakarta.enterprise.event.Observes;
//import jakarta.inject.Inject;
//import jakarta.inject.Named;
//
//@ApplicationScoped
//public class StartupService {
//
// @Inject
// AgroalDataSource dataSource;
//
// @Named("other-ds")
// @Inject
// AgroalDataSource otherDataSource;
//
// @Named("object-store-ds")
// @Inject
// AgroalDataSource objectStoreDataSource;
//
// public void initDataSources(@Observes StartupEvent event) {
// // force init of proxied beans
// dataSource.getMetrics();
// otherDataSource.getMetrics();
// objectStoreDataSource.getMetrics();
// }
//
//}
logs 2023-08-07 18:41:54,143 DEBUG [com.arj.ats.arjuna] (Transaction Expired Entry Monitor) ExpiredEntryMonitor running at Mon, 7 Aug 2023 18:41:54
2023-08-07 18:41:54,143 DEBUG [com.arj.ats.jbossatx] (Quarkus Main Thread) ARJUNA032013: Starting transaction recovery manager
2023-08-07 18:41:54,144 DEBUG [com.arj.ats.arjuna] (Transaction Expired Entry Monitor) ExpiredTransactionStatusManagerScanner - scanning to remove items from before Mon, 7 Aug 2023 06:41:54
2023-08-07 18:41:54,144 DEBUG [com.arj.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING
2023-08-07 18:41:54,144 TRACE [com.arj.ats.arjuna] (Transaction Expired Entry Monitor) InputObjectState::InputObjectState()
2023-08-07 18:41:54,144 DEBUG [com.arj.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning
2023-08-07 18:41:54,144 TRACE [com.arj.ats.arjuna] (Transaction Expired Entry Monitor) OutputObjectState::OutputObjectState()
2023-08-07 18:41:54,145 DEBUG [com.arj.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Mon, 7 Aug 2023 18:41:54
2023-08-07 18:41:54,145 WARN [com.arj.ats.arjuna] (Transaction Expired Entry Monitor) ARJUNA012251: allObjUids caught exception: java.sql.SQLException: This pool is closed and does not handle any more connections!
at io.agroal.pool.ConnectionPool.beforeAcquire(ConnectionPool.java:209)
at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:235)
at io.agroal.pool.DataSource.getConnection(DataSource.java:86)
at io.quarkus.narayana.jta.runtime.QuarkusDataSource.getConnection(QuarkusDataSource.java:38)
at com.arjuna.ats.internal.arjuna.objectstore.jdbc.accessors.DirectDataSourceJDBCAccess.getConnection(DirectDataSourceJDBCAccess.java:27)
at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCImple_driver.allObjUids(JDBCImple_driver.java:348)
at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCStore.allObjUids(JDBCStore.java:169)
at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCStore.allObjUids(JDBCStore.java:125)
at com.arjuna.ats.internal.arjuna.recovery.ExpiredTransactionStatusManagerScanner.scan(ExpiredTransactionStatusManagerScanner.java:81)
at com.arjuna.ats.internal.arjuna.recovery.ExpiredEntryMonitor.run(ExpiredEntryMonitor.java:171)
2023-08-07 18:41:54,145 TRACE [com.arj.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2023-08-07 18:41:54,145 DEBUG [com.arj.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass
2023-08-07 18:41:54,145 DEBUG [com.arj.ats.arjuna] (Transaction Expired Entry Monitor)
2023-08-07 18:41:54,146 TRACE [com.arj.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2023-08-07 18:41:54,146 WARN [com.arj.ats.arjuna] (Periodic Recovery) ARJUNA012251: allObjUids caught exception: java.sql.SQLException: This pool is closed and does not handle any more connections!
at io.agroal.pool.ConnectionPool.beforeAcquire(ConnectionPool.java:209)
at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:235)
at io.agroal.pool.DataSource.getConnection(DataSource.java:86)
at io.quarkus.narayana.jta.runtime.QuarkusDataSource.getConnection(QuarkusDataSource.java:38)
at com.arjuna.ats.internal.arjuna.objectstore.jdbc.accessors.DirectDataSourceJDBCAccess.getConnection(DirectDataSourceJDBCAccess.java:27)
at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCImple_driver.allObjUids(JDBCImple_driver.java:348)
at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCStore.allObjUids(JDBCStore.java:169)
at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCStore.allObjUids(JDBCStore.java:125)
at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkFirstPass(AtomicActionRecoveryModule.java:90)
at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:770)
at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:382)
2023-08-07 18:41:54,146 DEBUG [com.arj.ats.arjuna] (Periodic Recovery) Recovery module 'com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule@283cee3f' first pass processed
2023-08-07 18:41:54,147 DEBUG [com.arj.ats.jta] (Periodic Recovery) XARecoveryModule state change IDLE->FIRST_PASS
2023-08-07 18:41:54,147 DEBUG [com.arj.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass
2023-08-07 18:41:54,147 TRACE [com.arj.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
2023-08-07 18:41:54,147 TRACE [com.arj.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
2023-08-07 18:41:54,148 WARN [com.arj.ats.arjuna] (Periodic Recovery) ARJUNA012251: allObjUids caught exception: java.sql.SQLException: This pool is closed and does not handle any more connections!
at io.agroal.pool.ConnectionPool.beforeAcquire(ConnectionPool.java:209)
at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:235)
at io.agroal.pool.DataSource.getConnection(DataSource.java:86)
at io.quarkus.narayana.jta.runtime.QuarkusDataSource.getConnection(QuarkusDataSource.java:38)
at com.arjuna.ats.internal.arjuna.objectstore.jdbc.accessors.DirectDataSourceJDBCAccess.getConnection(DirectDataSourceJDBCAccess.java:27)
at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCImple_driver.allObjUids(JDBCImple_driver.java:348)
at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCStore.allObjUids(JDBCStore.java:169)
at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCStore.allObjUids(JDBCStore.java:125)
at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkFirstPass(XARecoveryModule.java:222)
at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkFirstPass(XARecoveryModule.java:191)
at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:770)
at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:382)
2023-08-07 18:41:54,148 WARN [com.arj.ats.jta] (Periodic Recovery) ARJUNA016001: could not get all object Uids.
2023-08-07 18:41:54,149 FINE [org.pos.Driver] (Periodic Recovery) Connecting with URL: jdbc:postgresql://localhost:5432/narayana_transaction_logs_db?adaptiveFetch=false&adaptiveFetchMaximum=-1&adaptiveFetchMinimum=0&allowEncodingChanges=false&ApplicationName=PostgreSQL+JDBC+Driver&autosave=never&binaryTransfer=true&binaryTransferDisable=&binaryTransferEnable=&cancelSignalTimeout=10&cleanupSavepoints=false&connectTimeout=10&databaseMetadataCacheFields=65536&databaseMetadataCacheFieldsMiB=5&defaultRowFetchSize=0&disableColumnSanitiser=false&escapeSyntaxCallMode=select&groupStartupParameters=false&gssEncMode=allow&gsslib=auto&gssResponseTimeout=5000&hideUnprivilegedObjects=false&hostRecheckSeconds=10&jaasApplicationName=pgjdbc&jaasLogin=true&loadBalanceHosts=false&loginTimeout=0&logServerErrorDetail=true&logUnclosedConnections=false&preferQueryMode=extended&preparedStatementCacheQueries=256&preparedStatementCacheSizeMiB=5&prepareThreshold=5"eReturningIdentifiers=true&readOnly=false&readOnlyMode=transaction&receiveBufferSize=-1&reWriteBatchedInserts=false&sendBufferSize=-1&socketTimeout=0&sslfactory=org.postgresql.ssl.LibPQFactory&sslResponseTimeout=5000&sspiServiceClass=POSTGRES&targetServerType=any&tcpKeepAlive=false&tcpNoDelay=true&unknownLength=2147483647&useSpnego=false&xmlFactoryFactory=
2023-08-07 18:41:54,149 FINE [org.pos.jdb.PgConnection] (Periodic Recovery) PostgreSQL JDBC Driver 42.6.0
2023-08-07 18:41:54,150 FINE [org.pos.jdb.PgConnection] (Periodic Recovery) setDefaultFetchSize = 0 |
|
I've tested steps to reproduce described in my previous comment with Quarkus main branch and same happens there, therefore this PR is not at fault. |
|
I don't know exactly what's going on. AFAICS, |
I debugged it in Naryana project, this is not issue of termination, but the when Naryana recorder starts recovery service, then it logs the exception. Maybe it is called too soon? I didn't go further ATM, so just FYI. |
|
@gsmet I think problem is that the old JDBC object store is used by ExpiredEntryMonitor for |
michalvavrik
approved these changes
Aug 8, 2023
|
Yes I was following the same path. I also have a big concern about BeanPopulator. I think the static map should be reset when Narayana is shut down but there’s no way to do it right now. Cc @mmusgrov and @zhfeng see the latest messages by @michalvavrik and myself. |
|
Btw you don’t need to add a file to reproduce it. Just starting the project in dev mode then pressing I’m also wondering if the StoreManager should be shut down. |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Related to #35238 , but I'm pretty certain we need to take a step back and redesign the startup and shutdown of the transaction manager and associated services.