search

asyncer-io / r2dbc-mysql

Reactive Relational Database Connectivity for MySQL. The official successor to mirromutth/r2dbc-mysql(dev.miku:r2dbc-mysql).
https://r2dbc.io
Apache License 2.0
195 stars 21 forks source link

Application fails to reconnect with DB after connection closed #128

Closed ssharan27 closed 1 year ago

ssharan27 commented 1 year ago

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:

1) Install and run mysql on local (i had used this doc for reference). It runs on port 3306 by default. 2) 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:

create database test;

3) 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)

mvn spring-boot:run
# 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)]

4) 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

5) 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>
jchrys commented 1 year ago

@ssharan27 Thank you for submitting a high-quality issue report for r2dbc-mysql! Your detailed input is greatly appreciated and will help us investigate and resolve the problem effectively. We value your contribution to improving the project and will keep you updated on our progress.

Thanks again!

jchrys commented 1 year ago

@ssharan27 After reviewing the issue, it appears that the problem lies with the connection pool rather than the driver. In HikariCP, when acquiring a connection, it attempts to retrieve it repeatedly within the maxAcquireTime, even if the connection is closed. On the other hand, r2dbc-pool seems to attempt a limited number of retries, specified by maxRetry.

To prevent the r2dbc connection pool from retrieving closed connections due to remote mysql server, I found that setting the maxIdleTime to a value lower than the wait_timeout of MySQL resolves the issue. This adjustment ensures that such occurrences no longer happen.

logging.level.org.springframework.r2dbc=DEBUG
spring.r2dbc.url=r2dbc:mysql://localhost:3306/test
spring.r2dbc.username=root
spring.r2dbc.password=password
spring.r2dbc.pool.max-idle-time=10s <-- added

if you believe there is a need to modify the current behavior of the connection pool, I recommend creating an issue on the following GitHub repository: https://github.com/r2dbc/r2dbc-pool. They will be better equipped to assist you with the necessary modifications.

Thanks a lot for your understanding and cooperation. 👍

ssharan27 commented 1 year ago

Thanks @jchrys and @JohnNiang for taking a look, will raise this on r2dbc pool repo. In the mean time will tweak the maxIdleTime value. Cheers :+1:

jchrys commented 1 year ago

Closed this issue cc @JohnNiang @ssharan27