Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Narayana transaction recovery stops work in DEV mode after hot reload #35839

Open
michalvavrik opened this issue Sep 10, 2023 · 12 comments
Open
Labels
area/devmode area/narayana Transactions / Narayana kind/bug Something isn't working

Comments

@michalvavrik
Copy link
Member

Describe the bug

When I change my application in DEV mode and the app is reload, Narayana keeps using the old (previous) Datasource connection even though pool has been closed and new one was created. Details in here #35242 (comment)

Expected behavior

After hot reload, my app still works.

Actual behavior

Warning is logged and periodic recovery doesn't work

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)

How to Reproduce?

Reproducer:

Output of uname -a or ver

Fedora

Output of java -version

17

GraalVM version (if different from Java)

23

Quarkus version or git rev

999-SNAPSHOT

Build tool (ie. output of mvnw --version or gradlew --version)

Apache Maven 3.9.3

Additional information

No response

@michalvavrik michalvavrik added kind/bug Something isn't working area/narayana Transactions / Narayana labels Sep 10, 2023
@michalvavrik
Copy link
Member Author

/cc @zhfeng @mmusgrov

@michalvavrik
Copy link
Member Author

Is this solved or on your radar @zhfeng @mmusgrov ?

@mmusgrov
Copy link
Contributor

@michalvavrik I don't recall ever investigating it. You raised the issue so could you not retest it? If not then the transaction team are quite busy: @marcosgopen or @jmfinelli are either of you able to provide Michal with any input on this issue.

@michalvavrik
Copy link
Member Author

@michalvavrik I don't recall ever investigating it. You raised the issue so could you not retest it? If not then the transaction team are quite busy: @marcosgopen or @jmfinelli are either of you able to provide Michal with any input on this issue.

copy that, thanks; I'll re-run the test later this week

@marcosgopen
Copy link
Contributor

Sure, I will have a look at it.

@marcosgopen
Copy link
Contributor

Hi @michalvavrik , I tested your reproducer but I got an error:
[INFO] Running org.acme.quickstart.JdbcObjectStoreTest [ERROR] Tests run: 5, Failures: 0, Errors: 1, Skipped: 4, Time elapsed: 4.396 s <<< FAILURE! - in org.acme.quickstart.JdbcObjectStoreTest [ERROR] org.acme.quickstart.JdbcObjectStoreTest.testTransactionsLogWithInjectedUserTransaction Time elapsed: 0.015 s <<< ERROR! java.lang.RuntimeException: java.lang.RuntimeException: Failed to load steps from class io.quarkus.resteasy.reactive.server.deployment.ResteasyReactiveProcessor at io.quarkus.test.junit.QuarkusTestExtension.throwBootFailureException(QuarkusTestExtension.java:643) at io.quarkus.test.junit.QuarkusTestExtension.interceptTestClassConstructor(QuarkusTestExtension.java:727) at java.base/java.util.Optional.orElseGet(Optional.java:364) at java.base/java.util.ArrayList.forEach(ArrayList.java:1511) at java.base/java.util.ArrayList.forEach(ArrayList.java:1511) Caused by: java.lang.RuntimeException: Failed to load steps from class io.quarkus.resteasy.reactive.server.deployment.ResteasyReactiveProcessor at io.quarkus.deployment.ExtensionLoader.loadStepsFrom(ExtensionLoader.java:164) at io.quarkus.deployment.QuarkusAugmentor.run(QuarkusAugmentor.java:107) at io.quarkus.runner.bootstrap.AugmentActionImpl.runAugment(AugmentActionImpl.java:333) at io.quarkus.runner.bootstrap.AugmentActionImpl.createInitialRuntimeApplication(AugmentActionImpl.java:254) at io.quarkus.runner.bootstrap.AugmentActionImpl.createInitialRuntimeApplication(AugmentActionImpl.java:60) at io.quarkus.test.junit.QuarkusTestExtension.doJavaStart(QuarkusTestExtension.java:224) at io.quarkus.test.junit.QuarkusTestExtension.ensureStarted(QuarkusTestExtension.java:610) at io.quarkus.test.junit.QuarkusTestExtension.beforeAll(QuarkusTestExtension.java:660) ... 1 more Caused by: java.lang.TypeNotPresentException: Type io.quarkus.vertx.http.deployment.EagerSecurityInterceptorBuildItem not present at java.base/java.lang.reflect.Executable.getGenericParameterTypes(Executable.java:298) at java.base/java.lang.reflect.Method.getGenericParameterTypes(Method.java:333) at java.base/java.lang.reflect.Executable.getAllGenericParameterTypes(Executable.java:317) at java.base/java.lang.reflect.Parameter.getParameterizedType(Parameter.java:202) at io.quarkus.deployment.ExtensionLoader.loadStepsFromClass(ExtensionLoader.java:493) at io.quarkus.deployment.ExtensionLoader.loadStepsFrom(ExtensionLoader.java:162) ... 8 more Caused by: java.lang.ClassNotFoundException: io.quarkus.vertx.http.deployment.EagerSecurityInterceptorBuildItem at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(BuiltinClassLoader.java:641) at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(ClassLoaders.java:188) at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:525) at io.quarkus.bootstrap.classloading.QuarkusClassLoader.loadClass(QuarkusClassLoader.java:518) at io.quarkus.bootstrap.classloading.QuarkusClassLoader.loadClass(QuarkusClassLoader.java:468) at java.base/java.lang.Class.forName0(Native Method) at java.base/java.lang.Class.forName(Class.java:467) ... 14 more
Are you also experiencing that? I have just built quarkus main branch and there might be 'breaking' changes. If you can still reproduce the issue, do you mind specify the 'git rev' of the quarkus you are using (e.g. the commit sha)? Thanks

@michalvavrik
Copy link
Member Author

michalvavrik commented Apr 27, 2024

sorry @marcosgopen , I had very busy week, sure, there were breaking changes in the meanwhile and I completely forgot about QS PR. Should probably rebase it and resolve conflicts. I'll fix the reproducer next week, thanks so far.

@gsmet
Copy link
Member

gsmet commented Aug 19, 2024

It would be interesting to see if this is still an issue.

@marcosgopen
Copy link
Contributor

@michalvavrik could you reproduce the issue with a more recent version of quarkus?

@michalvavrik
Copy link
Member Author

Hey, I'll answer later this week.

@michalvavrik
Copy link
Member Author

So, I have tried and I still can reproduce the original issue. Here is how:

git clone [email protected]:michalvavrik/quarkus-quickstarts.git -b feature/add-narayana-transaction-logs-qs
cd quarkus-quickstarts/narayana-transaction-logs-quickstart
docker-compose up
quarkus dev

Wait till Quarkus ready, then type 's', maybe wait again and try thrice. I am not quite sure how many times I have tried s as I had a long day. Here are logs I got:

[INFO] Invoking compiler:3.1:testCompile (default-testCompile) @ narayana-transaction-logs-quickstart
[INFO] Nothing to compile - all classes are up to date
Listening for transport dt_socket at address: 5005
__  ____  __  _____   ___  __ ____  ______ 
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/ 
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \   
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/   
2024-09-22 21:57:58,602 INFO  [io.quarkus] (Quarkus Main Thread) narayana-transaction-logs-quickstart 1.0.0-SNAPSHOT on JVM (powered by Quarkus 999-SNAPSHOT) started in 2.090s. Listening on: http://localhost:8080

2024-09-22 21:57:58,605 INFO  [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2024-09-22 21:57:58,605 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [agroal, cdi, jdbc-postgresql, narayana-jta, rest, smallrye-context-propagation, vertx]
2024-09-22 21:58:01,087 INFO  [io.qua.dep.dev.RuntimeUpdatesProcessor] (Aesh InputStream Reader) Restarting as requested by the user.
2024-09-22 21:58:01,090 INFO  [com.arj.ats.jbossatx] (Quarkus Main Thread) ARJUNA032014: Stopping transaction recovery manager
2024-09-22 21:58:01,099 INFO  [io.quarkus] (Quarkus Main Thread) narayana-transaction-logs-quickstart stopped in 0.011s
__  ____  __  _____   ___  __ ____  ______ 
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/ 
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \   
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/   
2024-09-22 21:58:01,460 INFO  [io.quarkus] (Quarkus Main Thread) narayana-transaction-logs-quickstart 1.0.0-SNAPSHOT on JVM (powered by Quarkus 999-SNAPSHOT) started in 0.359s. Listening on: http://localhost:8080

2024-09-22 21:58:01,461 INFO  [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2024-09-22 21:58:01,461 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [agroal, cdi, jdbc-postgresql, narayana-jta, rest, smallrye-context-propagation, vertx]
2024-09-22 21:58:01,462 INFO  [io.qua.dep.dev.RuntimeUpdatesProcessor] (Aesh InputStream Reader) Live reload total time: 0.377s 
2024-09-22 21:58:02,738 INFO  [io.qua.dep.dev.RuntimeUpdatesProcessor] (Aesh InputStream Reader) Restarting as requested by the user.
2024-09-22 21:58:02,743 INFO  [com.arj.ats.jbossatx] (Quarkus Main Thread) ARJUNA032014: Stopping transaction recovery manager
2024-09-22 21:58:02,748 INFO  [io.quarkus] (Quarkus Main Thread) narayana-transaction-logs-quickstart stopped in 0.008s
__  ____  __  _____   ___  __ ____  ______ 
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/ 
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \   
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/   
2024-09-22 21:58:03,051 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:247)
	at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:273)
	at io.agroal.pool.DataSource.getConnection(DataSource.java:86)
	at io.agroal.api.AgroalDataSource_4TkLOYZRnQnK5Mzj2yarinAMQzA_Synthetic_ClientProxy.getConnection(Unknown Source)
	at io.quarkus.narayana.jta.runtime.QuarkusDataSource.getConnection(QuarkusDataSource.java:38)
	at com.arjuna.ats.internal.arjuna.objectstore.jdbc.accessors.DirectDataSourceJDBCAccess.getConnection(DirectDataSourceJDBCAccess.java:25)
	at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCImple_driver.allObjUids(JDBCImple_driver.java:321)
	at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCStore.allObjUids(JDBCStore.java:142)
	at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCStore.allObjUids(JDBCStore.java:98)
	at com.arjuna.ats.internal.arjuna.recovery.ExpiredTransactionStatusManagerScanner.scan(ExpiredTransactionStatusManagerScanner.java:54)
	at com.arjuna.ats.internal.arjuna.recovery.ExpiredEntryMonitor.run(ExpiredEntryMonitor.java:144)


2024-09-22 21:58:03,051 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:247)
	at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:273)
	at io.agroal.pool.DataSource.getConnection(DataSource.java:86)
	at io.agroal.api.AgroalDataSource_4TkLOYZRnQnK5Mzj2yarinAMQzA_Synthetic_ClientProxy.getConnection(Unknown Source)
	at io.quarkus.narayana.jta.runtime.QuarkusDataSource.getConnection(QuarkusDataSource.java:38)
	at com.arjuna.ats.internal.arjuna.objectstore.jdbc.accessors.DirectDataSourceJDBCAccess.getConnection(DirectDataSourceJDBCAccess.java:25)
	at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCImple_driver.allObjUids(JDBCImple_driver.java:321)
	at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCStore.allObjUids(JDBCStore.java:142)
	at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCStore.allObjUids(JDBCStore.java:98)
	at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkFirstPass(AtomicActionRecoveryModule.java:63)
	at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:743)
	at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:355)


2024-09-22 21:58:03,053 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:247)
	at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:273)
	at io.agroal.pool.DataSource.getConnection(DataSource.java:86)
	at io.agroal.api.AgroalDataSource_4TkLOYZRnQnK5Mzj2yarinAMQzA_Synthetic_ClientProxy.getConnection(Unknown Source)
	at io.quarkus.narayana.jta.runtime.QuarkusDataSource.getConnection(QuarkusDataSource.java:38)
	at com.arjuna.ats.internal.arjuna.objectstore.jdbc.accessors.DirectDataSourceJDBCAccess.getConnection(DirectDataSourceJDBCAccess.java:25)
	at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCImple_driver.allObjUids(JDBCImple_driver.java:321)
	at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCStore.allObjUids(JDBCStore.java:142)
	at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCStore.allObjUids(JDBCStore.java:98)
	at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkFirstPass(XARecoveryModule.java:198)
	at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkFirstPass(XARecoveryModule.java:167)
	at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:743)
	at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:355)


2024-09-22 21:58:03,054 WARN  [com.arj.ats.jta] (Periodic Recovery) ARJUNA016001: could not get all object Uids.
2024-09-22 21:58:03,054 INFO  [io.quarkus] (Quarkus Main Thread) narayana-transaction-logs-quickstart 1.0.0-SNAPSHOT on JVM (powered by Quarkus 999-SNAPSHOT) started in 0.303s. Listening on: http://localhost:8080
2024-09-22 21:58:03,054 INFO  [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2024-09-22 21:58:03,055 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [agroal, cdi, jdbc-postgresql, narayana-jta, rest, smallrye-context-propagation, vertx]
2024-09-22 21:58:03,055 INFO  [io.qua.dep.dev.RuntimeUpdatesProcessor] (Aesh InputStream Reader) Live reload total time: 0.321s 

@marcosgopen
Copy link
Contributor

Thanks @michalvavrik for your reproducer, I menaged to reproduce it and I am working to understand what the problem is and solve it. I think that when the destroy method of QuarkusRecoveryService is executed we should also set to null the datasource of QuarkusDataSource. I'll keep you updated.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/devmode area/narayana Transactions / Narayana kind/bug Something isn't working
Projects
None yet
Development

No branches or pull requests

4 participants