Describe the bug
I have a Spring boot application which I am migrating to Spring Boot 3. I am using the r2dbc mysql driver to connect with db. I am facing issues as queries are randomly failing. Error occurs when idle connection(s) are closed by the DB, queries coming post connection closure fail to execute with exception org.springframework.dao.DataAccessResourceFailureException: Failed to obtain R2DBC Connection
To Reproduce
platform: Ubuntu 22.04
jdk version: openjdk-20
maven version: 3.8.1
spring-boot version: 3.1.0
r2dbc-mysql version: 1.0.2
Sample repo link
Complete app log gist
Steps:
- Install and run mysql on local (i had used this doc for reference). It runs on port
3306
by default.
- Reduce
idle_timeout
and interactive_timeout
to 180 by adding following configuration to /etc/alternatives/my.cnf
(Reducing these timeout values causes the DB to close idle connections after 3 minutes thus saving time :P):
# default was 28800 seconds
[mysqld]
interactive_timeout=180
wait_timeout=180
create a test database, the reproducer application uses the database: test
. On mysql CLI run:
- Clone and run the reproducer spring boot application using maven, by default the application will run on port 8080.
(Check the application.properties to configure database related properties according to your local setup)
# curl to get all table rows
curl 'http://localhost:8080/get'
# api response will look something like this:
# [{"id":1,"name":"abc","age":21},{"id":2,"name":"bbd","age":12},{"id":3,"name":"abbd","age":31},{"id":4,"name":"abv","age":21},{"id":5,"name":"abd","age":25},{"id":6,"name":"aba","age":24},{"id":7,"name":"abe","age":23},{"id":8,"name":"abd","age":25},{"id":9,"name":"aba","age":24},{"id":10,"name":"abe","age":23}]
# curl to insert multiple rows to table
curl -X POST 'http://localhost:8080/save' -d '[{"name" : "john", "age" : 33}, {"name" : "jonah", "age" : 34}]' -H "Content-Type: application/json"
# response looks like this
# [{"id":11,"name":"john","age":33},{"id":12,"name":"jonah","age":34}]%
Hit these endpoints to validate the application running correctly.
2023-06-16T12:30:09.044+05:30 INFO 1100092 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path ''
2023-06-16T12:30:09.052+05:30 INFO 1100092 --- [ main] com.example.Main : Started Main in 1.827 seconds (process running for 2.025)
2023-06-16T12:31:12.503+05:30 INFO 1100092 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
2023-06-16T12:31:12.503+05:30 INFO 1100092 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
2023-06-16T12:31:12.503+05:30 INFO 1100092 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Completed initialization in 0 ms
2023-06-16T12:31:12.543+05:30 DEBUG 1100092 --- [nio-8080-exec-1] o.s.r2dbc.core.DefaultDatabaseClient : Executing SQL statement [SELECT test.* FROM test]
2023-06-16T12:31:12.560+05:30 INFO 1100092 --- [tor-tcp-epoll-2] com.example.service.TestService : Found data: [Test(id=1, name=abc, age=21), Test(id=2, name=bbd, age=12), Test(id=3, name=abbd, age=31), Test(id=4, name=abv, age=21), Test(id=5, name=abd, age=25), Test(id=6, name=aba, age=24), Test(id=7, name=abe, age=23), Test(id=8, name=abd, age=25), Test(id=9, name=aba, age=24), Test(id=10, name=abe, age=23)]
- Now wait for 3 minutes (as we set the idle and interactive timeout to 3 minutes) so that the DB starts evicting idle connections. This can be seen using the
show processlist;
command. It will look something like this:
mysql> show processlist;
+-----+-----------------+-----------------+------+---------+--------+------------------------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+-----+-----------------+-----------------+------+---------+--------+------------------------+------------------+
| 5 | event_scheduler | localhost | NULL | Daemon | 158938 | Waiting on empty queue | NULL |
| 169 | root | localhost:34600 | test | Sleep | 165 | | NULL |
| 170 | root | localhost:34608 | test | Sleep | 165 | | NULL |
| 171 | root | localhost:34624 | test | Sleep | 165 | | NULL |
| 172 | root | localhost:34634 | test | Sleep | 165 | | NULL |
| 173 | root | localhost:34646 | test | Sleep | 165 | | NULL |
| 174 | root | localhost:34654 | test | Sleep | 165 | | NULL |
| 175 | root | localhost:34658 | test | Sleep | 165 | | NULL |
| 176 | root | localhost:34682 | test | Sleep | 165 | | NULL |
| 177 | root | localhost:34674 | test | Sleep | 165 | | NULL |
| 178 | root | localhost:34694 | test | Sleep | 101 | | NULL |
| 179 | root | localhost | test | Query | 0 | init | show processlist |
+-----+-----------------+-----------------+------+---------+--------+------------------------+------------------+
12 rows in set (0.00 sec)
mysql> show processlist;
+-----+-----------------+-----------------+------+---------+--------+------------------------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+-----+-----------------+-----------------+------+---------+--------+------------------------+------------------+
| 5 | event_scheduler | localhost | NULL | Daemon | 158952 | Waiting on empty queue | NULL |
| 169 | root | localhost:34600 | test | Sleep | 179 | | NULL |
| 170 | root | localhost:34608 | test | Sleep | 179 | | NULL |
| 171 | root | localhost:34624 | test | Sleep | 179 | | NULL |
| 172 | root | localhost:34634 | test | Sleep | 179 | | NULL |
| 173 | root | localhost:34646 | test | Sleep | 179 | | NULL |
| 174 | root | localhost:34654 | test | Sleep | 179 | | NULL |
| 175 | root | localhost:34658 | test | Sleep | 179 | | NULL |
| 176 | root | localhost:34682 | test | Sleep | 179 | | NULL |
| 177 | root | localhost:34674 | test | Sleep | 179 | | NULL |
| 178 | root | localhost:34694 | test | Sleep | 115 | | NULL |
| 179 | root | localhost | test | Query | 0 | init | show processlist |
+-----+-----------------+-----------------+------+---------+--------+------------------------+------------------+
12 rows in set (0.01 sec)
mysql> show processlist;
+-----+-----------------+-----------------+------+---------+--------+------------------------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+-----+-----------------+-----------------+------+---------+--------+------------------------+------------------+
| 5 | event_scheduler | localhost | NULL | Daemon | 158955 | Waiting on empty queue | NULL |
| 178 | root | localhost:34694 | test | Sleep | 118 | | NULL |
| 179 | root | localhost | test | Query | 0 | init | show processlist |
+-----+-----------------+-----------------+------+---------+--------+------------------------+------------------+
3 rows in set (0.00 sec)
mysql> show processlist;
+-----+-----------------+-----------------+------+---------+--------+------------------------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+-----+-----------------+-----------------+------+---------+--------+------------------------+------------------+
| 5 | event_scheduler | localhost | NULL | Daemon | 159015 | Waiting on empty queue | NULL |
| 178 | root | localhost:34694 | test | Sleep | 178 | | NULL |
| 179 | root | localhost | test | Query | 0 | init | show processlist |
+-----+-----------------+-----------------+------+---------+--------+------------------------+------------------+
3 rows in set (0.00 sec)
mysql> show processlist;
+-----+-----------------+-----------+------+---------+--------+------------------------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+-----+-----------------+-----------+------+---------+--------+------------------------+------------------+
| 5 | event_scheduler | localhost | NULL | Daemon | 159017 | Waiting on empty queue | NULL |
| 179 | root | localhost | test | Query | 0 | init | show processlist |
+-----+-----------------+-----------+------+---------+--------+------------------------+------------------+
2 rows in set (0.00 sec)
This is also indicated in the application logs:
2023-06-16T12:33:08.833+05:30 WARN 1100092 --- [tor-tcp-epoll-2] i.a.r.mysql.client.MessageDuplexCodec : Connection has been closed by peer
2023-06-16T12:33:08.893+05:30 WARN 1100092 --- [tor-tcp-epoll-2] i.a.r.mysql.client.MessageDuplexCodec : Connection has been closed by peer
2023-06-16T12:33:08.905+05:30 WARN 1100092 --- [tor-tcp-epoll-2] i.a.r.mysql.client.MessageDuplexCodec : Connection has been closed by peer
2023-06-16T12:33:08.910+05:30 WARN 1100092 --- [tor-tcp-epoll-2] i.a.r.mysql.client.MessageDuplexCodec : Connection has been closed by peer
2023-06-16T12:33:08.913+05:30 WARN 1100092 --- [tor-tcp-epoll-2] i.a.r.mysql.client.MessageDuplexCodec : Connection has been closed by peer
2023-06-16T12:33:08.914+05:30 WARN 1100092 --- [tor-tcp-epoll-2] i.a.r.mysql.client.MessageDuplexCodec : Connection has been closed by peer
2023-06-16T12:33:08.914+05:30 WARN 1100092 --- [tor-tcp-epoll-2] i.a.r.mysql.client.MessageDuplexCodec : Connection has been closed by peer
2023-06-16T12:33:08.917+05:30 WARN 1100092 --- [tor-tcp-epoll-2] i.a.r.mysql.client.MessageDuplexCodec : Connection has been closed by peer
2023-06-16T12:33:08.917+05:30 WARN 1100092 --- [tor-tcp-epoll-2] i.a.r.mysql.client.MessageDuplexCodec : Connection has been closed by peer
2023-06-16T12:34:12.647+05:30 WARN 1100092 --- [tor-tcp-epoll-2] i.a.r.mysql.client.MessageDuplexCodec : Connection has been closed by peer
- Now hit the api using the previous curls. It will give error response:
curl -i 'http://localhost:8080/get'
## internal server error response ##
# {"timestamp":"2023-06-16T07:37:16.990+00:00","status":500,"error":"Internal Server Error","path":"/get"}%
curl -i -X POST 'http://localhost:8080/save' -d '[{"name" : "john", "age" : 33}, {"name" : "jonah", "age" : 34}]' -H "Content-Type: application/json"
## internal server error response ##
# {"timestamp":"2023-06-16T07:37:12.222+00:00","status":500,"error":"Internal Server Error","path":"/save"}%
Stacktrace from application logs:
2023-06-16T12:34:19.019+05:30 ERROR 1100092 --- [tor-tcp-epoll-2] com.example.service.TestService : Error
org.springframework.dao.DataAccessResourceFailureException: Failed to obtain R2DBC Connection
at org.springframework.r2dbc.connection.ConnectionFactoryUtils.lambda$getConnection$0(ConnectionFactoryUtils.java:90) ~[spring-r2dbc-6.0.7.jar:6.0.7]
at reactor.core.publisher.Mono.lambda$onErrorMap$28(Mono.java:3773) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:94) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:106) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.FluxRetry$RetrySubscriber.onError(FluxRetry.java:95) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:241) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:315) ~[reactor-core-3.5.6.jar:3.5.6]
at io.r2dbc.pool.MonoDiscardOnCancel$MonoDiscardOnCancelSubscriber.onError(MonoDiscardOnCancel.java:98) ~[r2dbc-pool-1.0.0.RELEASE.jar:1.0.0.RELEASE]
at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:106) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onError(MonoIgnoreThen.java:278) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:231) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:203) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.onComplete(FluxDoFinally.java:128) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.onComplete(FluxDoFinally.java:128) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:209) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.Operators.complete(Operators.java:137) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.netty.FutureMono.doSubscribe(FutureMono.java:122) ~[reactor-netty-core-1.1.7.jar:1.1.7]
at reactor.netty.FutureMono$DeferredFutureMono.subscribe(FutureMono.java:114) ~[reactor-netty-core-1.1.7.jar:1.1.7]
at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:240) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:203) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onComplete(Operators.java:2205) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoFlatMap$FlatMapMain.onComplete(MonoFlatMap.java:189) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoCreate$DefaultMonoSink.success(MonoCreate.java:140) ~[reactor-core-3.5.6.jar:3.5.6]
at io.asyncer.r2dbc.mysql.client.ReactorNettyClient.lambda$close$11(ReactorNettyClient.java:200) ~[r2dbc-mysql-1.0.2.jar:1.0.2]
at reactor.core.publisher.MonoCreate.subscribe(MonoCreate.java:58) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.Mono.subscribe(Mono.java:4485) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:263) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:51) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.Mono.subscribe(Mono.java:4485) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:263) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:51) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.Mono.subscribe(Mono.java:4485) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onError(MonoIgnoreThen.java:278) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onError(MonoIgnoreElements.java:84) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onNext(FluxHandleFuseable.java:200) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoSupplier$MonoSupplierSubscription.request(MonoSupplier.java:145) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.request(FluxHandleFuseable.java:259) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onSubscribe(MonoIgnoreElements.java:72) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onSubscribe(FluxHandleFuseable.java:163) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoSupplier.subscribe(MonoSupplier.java:48) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.Mono.subscribe(Mono.java:4485) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:263) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:51) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) ~[reactor-core-3.5.6.jar:3.5.6]
at io.r2dbc.pool.MonoDiscardOnCancel.subscribe(MonoDiscardOnCancel.java:50) ~[r2dbc-pool-1.0.0.RELEASE.jar:1.0.0.RELEASE]
at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:165) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.pool.AbstractPool$Borrower.deliver(AbstractPool.java:467) ~[reactor-pool-1.0.0.jar:1.0.0]
at reactor.pool.SimpleDequePool.lambda$drainLoop$8(SimpleDequePool.java:368) ~[reactor-pool-1.0.0.jar:1.0.0]
at reactor.core.scheduler.ImmediateScheduler.schedule(ImmediateScheduler.java:52) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.pool.SimpleDequePool.drainLoop(SimpleDequePool.java:368) ~[reactor-pool-1.0.0.jar:1.0.0]
at reactor.pool.SimpleDequePool.pendingOffer(SimpleDequePool.java:598) ~[reactor-pool-1.0.0.jar:1.0.0]
at reactor.pool.SimpleDequePool.doAcquire(SimpleDequePool.java:294) ~[reactor-pool-1.0.0.jar:1.0.0]
at reactor.pool.AbstractPool$Borrower.request(AbstractPool.java:430) ~[reactor-pool-1.0.0.jar:1.0.0]
at reactor.core.publisher.MonoFlatMap$FlatMapMain.request(MonoFlatMap.java:194) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:2341) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:2215) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoFlatMap$FlatMapMain.onSubscribe(MonoFlatMap.java:117) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.pool.SimpleDequePool$QueueBorrowerMono.subscribe(SimpleDequePool.java:716) ~[reactor-pool-1.0.0.jar:1.0.0]
at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.FluxRetry$RetrySubscriber.resubscribe(FluxRetry.java:117) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.FluxRetry$RetrySubscriber.onError(FluxRetry.java:101) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:241) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:315) ~[reactor-core-3.5.6.jar:3.5.6]
at io.r2dbc.pool.MonoDiscardOnCancel$MonoDiscardOnCancelSubscriber.onError(MonoDiscardOnCancel.java:98) ~[r2dbc-pool-1.0.0.RELEASE.jar:1.0.0.RELEASE]
at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:106) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onError(MonoIgnoreThen.java:278) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:231) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:203) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.onComplete(FluxDoFinally.java:128) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.onComplete(FluxDoFinally.java:128) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:209) ~[reactor-core-3.5.6.jar:3.5.6]
at reactor.netty.FutureMono$FutureSubscription.operationComplete(FutureMono.java:196) ~[reactor-netty-core-1.1.7.jar:1.1.7]
at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:590) ~[netty-common-4.1.92.Final.jar:4.1.92.Final]
at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:557) ~[netty-common-4.1.92.Final.jar:4.1.92.Final]
at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:492) ~[netty-common-4.1.92.Final.jar:4.1.92.Final]
at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:636) ~[netty-common-4.1.92.Final.jar:4.1.92.Final]
at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:625) ~[netty-common-4.1.92.Final.jar:4.1.92.Final]
at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:105) ~[netty-common-4.1.92.Final.jar:4.1.92.Final]
at io.netty.channel.DefaultChannelPromise.trySuccess(DefaultChannelPromise.java:84) ~[netty-transport-4.1.92.Final.jar:4.1.92.Final]
at io.netty.channel.AbstractChannel$AbstractUnsafe.safeSetSuccess(AbstractChannel.java:990) ~[netty-transport-4.1.92.Final.jar:4.1.92.Final]
at io.netty.channel.AbstractChannel$AbstractUnsafe.close(AbstractChannel.java:686) ~[netty-transport-4.1.92.Final.jar:4.1.92.Final]
at io.netty.channel.AbstractChannel$AbstractUnsafe.close(AbstractChannel.java:620) ~[netty-transport-4.1.92.Final.jar:4.1.92.Final]
at io.netty.channel.DefaultChannelPipeline$HeadContext.close(DefaultChannelPipeline.java:1352) ~[netty-transport-4.1.92.Final.jar:4.1.92.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeClose(AbstractChannelHandlerContext.java:749) ~[netty-transport-4.1.92.Final.jar:4.1.92.Final]
at io.netty.channel.AbstractChannelHandlerContext.access$1200(AbstractChannelHandlerContext.java:61) ~[netty-transport-4.1.92.Final.jar:4.1.92.Final]
at io.netty.channel.AbstractChannelHandlerContext$11.run(AbstractChannelHandlerContext.java:732) ~[netty-transport-4.1.92.Final.jar:4.1.92.Final]
at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174) ~[netty-common-4.1.92.Final.jar:4.1.92.Final]
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167) ~[netty-common-4.1.92.Final.jar:4.1.92.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470) ~[netty-common-4.1.92.Final.jar:4.1.92.Final]
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:403) ~[netty-transport-classes-epoll-4.1.92.Final.jar:4.1.92.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[netty-common-4.1.92.Final.jar:4.1.92.Final]
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.92.Final.jar:4.1.92.Final]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.92.Final.jar:4.1.92.Final]
at java.base/java.lang.Thread.run(Thread.java:1623) ~[na:na]
Caused by: io.r2dbc.spi.R2dbcNonTransientResourceException: Connection validation failed
at io.r2dbc.pool.Validation.lambda$validate$2(Validation.java:45) ~[r2dbc-pool-1.0.0.RELEASE.jar:1.0.0.RELEASE]
at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onNext(FluxHandleFuseable.java:178) ~[reactor-core-3.5.6.jar:3.5.6]
... 60 common frames omitted
Expected behavior
Expect the driver to reconnect upon connection validation failure and then execute the queries as is the case with the 'traditional' JPA which uses JDBC driver. In case of JDBC driver, application is able to recover from the connection validation error and return the response.
Additional context
If required, I can add another sample application that uses JDBC which executes queries as expected with the same reproduction steps mentioned previously, for now I have only added the application logs, config properties and relevant dependencies from pom.
application.properties:
server.port=9091
spring.datasource.url=jdbc:mysql://localhost:3306/test
spring.datasource.username=root
spring.datasource.password=password
logs:
2023-06-15 16:04:32.866 INFO [,,] 1014806 --- [ restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 9091 (http) with context path ''
2023-06-15 16:04:32.905 INFO [,,] 1014806 --- [ restartedMain] com.example.toy.ToyApplication : Started ToyApplication in 4.993 seconds (JVM running for 5.295)
2023-06-15 16:04:36.379 INFO [,03342ce960139f4d,03342ce960139f4d] 1014806 --- [nio-9091-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
2023-06-15 16:04:36.379 INFO [,03342ce960139f4d,03342ce960139f4d] 1014806 --- [nio-9091-exec-1] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
2023-06-15 16:04:36.380 INFO [,03342ce960139f4d,03342ce960139f4d] 1014806 --- [nio-9091-exec-1] o.s.web.servlet.DispatcherServlet : Completed initialization in 1 ms
2023-06-15 16:04:36.491 INFO [,03342ce960139f4d,03342ce960139f4d] 1014806 --- [nio-9091-exec-1] com.example.toy.service.TestService : [Test(id=1, name=abc, age=21), Test(id=2, name=bbd, age=12), Test(id=3, name=abbd, age=31), Test(id=4, name=abv, age=21)]
2023-06-16 13:47:04.395 WARN [,9700876eff472209,9700876eff472209] 1014806 --- [nio-9091-exec-3] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@16fc706c (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.
2023-06-16 13:47:04.397 WARN [,9700876eff472209,9700876eff472209] 1014806 --- [nio-9091-exec-3] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@49a960da (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.
2023-06-16 13:47:04.398 WARN [,9700876eff472209,9700876eff472209] 1014806 --- [nio-9091-exec-3] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@251daf0 (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.
2023-06-16 13:47:04.399 WARN [,9700876eff472209,9700876eff472209] 1014806 --- [nio-9091-exec-3] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@775bb5c6 (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.
2023-06-16 13:47:04.399 WARN [,9700876eff472209,9700876eff472209] 1014806 --- [nio-9091-exec-3] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@3745444b (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.
2023-06-16 13:47:04.400 WARN [,9700876eff472209,9700876eff472209] 1014806 --- [nio-9091-exec-3] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@35685dc9 (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.
2023-06-16 13:47:04.400 WARN [,9700876eff472209,9700876eff472209] 1014806 --- [nio-9091-exec-3] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@396297ce (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.
2023-06-16 13:47:04.401 WARN [,9700876eff472209,9700876eff472209] 1014806 --- [nio-9091-exec-3] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@133de0a1 (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.
2023-06-16 13:47:04.402 WARN [,9700876eff472209,9700876eff472209] 1014806 --- [nio-9091-exec-3] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@54c73f8a (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.
2023-06-16 13:47:04.402 WARN [,9700876eff472209,9700876eff472209] 1014806 --- [nio-9091-exec-3] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@2883e55b (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.
2023-06-16 13:47:04.408 INFO [,9700876eff472209,9700876eff472209] 1014806 --- [nio-9091-exec-3] com.example.toy.service.TestService : Found: [Test(id=1, name=abc, age=21), Test(id=2, name=bbd, age=12), Test(id=3, name=abbd, age=31), Test(id=4, name=abv, age=21), Test(id=5, name=abd, age=25), Test(id=6, name=aba, age=24), Test(id=7, name=abe, age=23), Test(id=8, name=abd, age=25), Test(id=9, name=aba, age=24), Test(id=10, name=abe, age=23), Test(id=11, name=john, age=33), Test(id=12, name=jonah, age=34)]
dependencies:
<dependency>
<groupId>org.springframework.data</groupId>
<artifactId>spring-data-relational</artifactId>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-data-jpa</artifactId>
</dependency>
<dependency>
<groupId>mysql</groupId>
<artifactId>mysql-connector-java</artifactId>
<version>8.0.33</version>
</dependency>