search

snowdrop / narayana-spring-boot

Narayana Spring Boot autoconfiguration and starter
Apache License 2.0
46 stars 43 forks source link

Update Agroal to 2.4 #147

Closed graben closed 4 months ago

graben commented 5 months ago

@barreiro: Maybe a regression in latest Agroal version? I'll have a look into the test case either way.

barreiro commented 5 months ago

@graben maybe, although the Closing open connection(s) prior to commit are a bit suspicious. maybe the pool size for the test needs to be increased ??

graben commented 5 months ago

I'm actually thinking it could be something like timing between parallel threads. But this is currently only a hypothesis.

graben commented 5 months ago

@barreiro : Setting the wait timeout to a larger value helps, but it needs closing the complete pool of 10 Connections? I think something is going wrong.

2024-05-23T18:31:58.560+02:00  INFO 20632 --- [riodic Recovery] d.s.boot.narayana.utils.BytemanHelper    : dev.snowdrop.boot.narayana.utils.BytemanHelper increment commits counter: 2
2024-05-23T18:31:58.580+02:00  INFO 20632 --- [ntContainer#0-1] d.s.boot.narayana.app.MessagesService    : Received message 'test-message'
2024-05-23T18:31:59.540+02:00  INFO 20632 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-23T18:31:59.543+02:00  WARN 20632 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-23T18:31:59.548+02:00  INFO 20632 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[]'
2024-05-23T18:32:00.561+02:00  INFO 20632 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-23T18:32:00.567+02:00  WARN 20632 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-23T18:32:00.569+02:00  INFO 20632 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[]'
2024-05-23T18:32:01.582+02:00  INFO 20632 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-23T18:32:01.587+02:00  WARN 20632 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-23T18:32:01.588+02:00  INFO 20632 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[]'
2024-05-23T18:32:02.599+02:00  INFO 20632 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-23T18:32:02.605+02:00  WARN 20632 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-23T18:32:02.606+02:00  INFO 20632 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[]'
2024-05-23T18:32:03.619+02:00  INFO 20632 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-23T18:32:03.625+02:00  WARN 20632 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-23T18:32:03.625+02:00  INFO 20632 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[]'
2024-05-23T18:32:04.641+02:00  INFO 20632 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-23T18:32:04.646+02:00  WARN 20632 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-23T18:32:04.647+02:00  INFO 20632 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[]'
2024-05-23T18:32:05.651+02:00  INFO 20632 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-23T18:32:05.656+02:00  WARN 20632 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-23T18:32:05.656+02:00  INFO 20632 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[]'
2024-05-23T18:32:06.670+02:00  INFO 20632 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-23T18:32:06.674+02:00  WARN 20632 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-23T18:32:06.675+02:00  INFO 20632 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[]'
2024-05-23T18:32:07.686+02:00  INFO 20632 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-23T18:32:07.691+02:00  WARN 20632 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-23T18:32:07.692+02:00  INFO 20632 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[]'
2024-05-23T18:32:08.693+02:00  INFO 20632 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-23T18:32:08.708+02:00  WARN 20632 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-23T18:32:08.709+02:00  INFO 20632 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[Entry{id=1, value='test-value'}]'
barreiro commented 5 months ago

that message means that the connection wrappers are still open on commit and Agroal is closing them for you (to prevent concurrent calls with commit, and eventual leaks). they should be closed beforehand.

because now the recovery is executed from the connections on the pool, there can be more pressure on the number of available connections. (or can be an issue too, of course)

graben commented 5 months ago

Setting spring.datasource.agroal.recoveryUsername=sa to force the old recovery way works without "noise".

barreiro commented 5 months ago

I'll have a look at the test case later today.

graben commented 5 months ago

Setting logging output to DEBUG. It seems test thread and recovery thread are struggling with the same connection. Recovery succeeds after a new connection is created because recovery thread locks the former one.

2024-05-24T10:23:23.545+02:00  INFO 7400 --- [           main] d.s.boot.narayana.utils.BytemanHelper    : dev.snowdrop.boot.narayana.utils.BytemanHelper fail first commit
Fail before commit : org.jboss.byteman.rule.exception.ExecuteException: MethodExpression.interpret : exception invoking method failFirstCommit file dev.snowdrop.boot.narayana.pooled.PooledRecoveryIT+testCrashBeforeCommit line 8
2024-05-24T10:23:23.546+02:00  INFO 7400 --- [           main] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:23.632+02:00 DEBUG 7400 --- [      agroal-11] io.agroal.api.AgroalDataSource.'jdbc'    : Created connection conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:23.635+02:00 DEBUG 7400 --- [           main] io.agroal.api.AgroalDataSource.'jdbc'    : Connection acquired conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:23.641+02:00  WARN 7400 --- [           main] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-24T10:23:23.643+02:00 DEBUG 7400 --- [           main] io.agroal.api.AgroalDataSource.'jdbc'    : Connection return conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:23.643+02:00  INFO 7400 --- [           main] d.s.boot.narayana.app.EntriesService     : Returning entries '[]'
2024-05-24T10:23:24.678+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:25.696+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:26.702+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:27.705+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:28.720+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:29.723+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:30.730+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:31.734+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:32.747+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:33.752+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:34.766+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:35.772+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:36.776+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:37.779+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:38.792+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:38.990+02:00 DEBUG 7400 --- [riodic Recovery] io.agroal.api.AgroalDataSource.'jdbc'    : Connection acquired conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:39.797+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:40.808+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:41.821+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:42.835+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:43.842+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:44.844+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:45.850+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:46.861+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:47.870+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:48.879+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[]'
2024-05-24T10:23:49.013+02:00  INFO 7400 --- [riodic Recovery] d.s.boot.narayana.utils.BytemanHelper    : dev.snowdrop.boot.narayana.utils.BytemanHelper increment commits counter: 2
2024-05-24T10:23:49.018+02:00 DEBUG 7400 --- [riodic Recovery] io.agroal.api.AgroalDataSource.'jdbc'    : Connection return conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:49.028+02:00  INFO 7400 --- [ntContainer#0-1] d.s.boot.narayana.app.MessagesService    : Received message 'test-message'
2024-05-24T10:23:49.880+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-24T10:23:49.886+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection acquired conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:49.887+02:00  WARN 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-24T10:23:49.887+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection return conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:49.887+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[]'
2024-05-24T10:23:50.891+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-24T10:23:50.896+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection acquired conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:50.897+02:00  WARN 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-24T10:23:50.898+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection return conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:50.898+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[]'
2024-05-24T10:23:51.904+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-24T10:23:51.909+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection acquired conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:51.911+02:00  WARN 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-24T10:23:51.912+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection return conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:51.913+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[]'
2024-05-24T10:23:52.927+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-24T10:23:52.932+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection acquired conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:52.932+02:00  WARN 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-24T10:23:52.933+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection return conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:52.933+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[]'
2024-05-24T10:23:53.946+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-24T10:23:53.950+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection acquired conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:53.951+02:00  WARN 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-24T10:23:53.952+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection return conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:53.953+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[]'
2024-05-24T10:23:54.955+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-24T10:23:54.955+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection acquired conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:54.956+02:00  WARN 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-24T10:23:54.957+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection return conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:54.957+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[]'
2024-05-24T10:23:55.960+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-24T10:23:55.960+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection acquired conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:55.961+02:00  WARN 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-24T10:23:55.961+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection return conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:55.961+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[]'
2024-05-24T10:23:56.974+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-24T10:23:56.975+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection acquired conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:56.976+02:00  WARN 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-24T10:23:56.976+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection return conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:56.976+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[]'
2024-05-24T10:23:57.990+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-24T10:23:57.991+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection acquired conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:57.992+02:00  WARN 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-24T10:23:57.993+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection return conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:57.993+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[]'
2024-05-24T10:23:59.003+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-24T10:23:59.004+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection acquired conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:59.005+02:00  WARN 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-24T10:23:59.005+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection return conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:23:59.005+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[]'
2024-05-24T10:23:59.058+02:00 DEBUG 7400 --- [riodic Recovery] io.agroal.api.AgroalDataSource.'jdbc'    : Connection acquired conn5: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:24:00.019+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.MessagesService    : Returning received messages '[test-message]'
2024-05-24T10:24:00.021+02:00 DEBUG 7400 --- [      agroal-11] io.agroal.api.AgroalDataSource.'jdbc'    : Created connection conn8: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:24:00.021+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection acquired conn8: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:24:00.028+02:00  WARN 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Closing open connection(s) prior to commit
2024-05-24T10:24:00.029+02:00 DEBUG 7400 --- [very to happen]] io.agroal.api.AgroalDataSource.'jdbc'    : Connection return conn8: url=jdbc:h2:mem:jdbc user=SA
2024-05-24T10:24:00.029+02:00  INFO 7400 --- [very to happen]] d.s.boot.narayana.app.EntriesService     : Returning entries '[Entry{id=1, value='test-value'}]'
graben commented 5 months ago

@barreiro : I just did a little "dirty" experiment. Instead of calling handler.transactionEnd(); in XAConnectionWrapper.close() I called handler.setFlushOnly(); to force connection to get removed from pool. After that, the recovery process gets finished immediately. IHMO it looks like a connection used by recovery process couldn't been brought back to pool this way. Maybe some internal state gets wrong or something needs to be refreshed?

graben commented 5 months ago

Doing a rollback() on rawConnection() just before calling handler.transactionEnd(); works, too. Might be an issue with H2 that doing recovery with the same connection that is used in between the application is causing no data transfer afterwards.

Got it working with PostgreSQL, SQL Server and Derby. Needs some "hack" because databases react different with locking tables after the crash letting assertEntriesAfterCrash to stuck until recovery, causing the test to fail while recovering was successful. Completely fails with MariaDB and partly HSQL. There seems to be problems with doing querying and recovering over different connections.

IMHO, actually no bug in Agroal, but stupid behaviour of H2 the test has to deal with.