r2dbc pool background eviction causes DatabaseClientReactiveAdapter to close #789
Description
When using com.google.cloud:cloud-spanner-spring-data-r2dbc:1.2.2 and com.google.cloud:cloud-spanner-r2dbc:1.3.0 there is a property pre-configured in r2dbc-pool (spring.r2dbc.pool.max-idle-time, default value is 30m). This property configures how long a connection should be idle within the r2dbc connection pool before it is removed. The reactor pool is removing the idle connections from the pool, which calls the close method on DatabaseClientReactiveAdapter and sets DatabaseClientReactiveAdapter.active to false. When subsequent requests (including health checks) are sent to Spanner, the following exception is being thrown and there is no way to recover from it. This behavior can easily and quickly be triggered by setting spring.r2dbc.pool.max-idle-time to 30s (or some other small duration).
io.r2dbc.spi.R2dbcNonTransientResourceException: Connection validation failed
at io.r2dbc.pool.Validation.lambda$validate$2(Validation.java:45) ~[r2dbc-pool-1.0.1.RELEASE.jar:1.0.1.RELEASE]
Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException:
Assembly trace from producer [reactor.core.publisher.FluxHandleFuseable] :
reactor.core.publisher.Flux.handle(Flux.java:6041)
io.r2dbc.pool.Validation.validate(Validation.java:38)
Error has been observed at the following site(s):
*__________Flux.handle ⇢ at io.r2dbc.pool.Validation.validate(Validation.java:38)
|_ Flux.then ⇢ at io.r2dbc.pool.Validation.validate(Validation.java:46)
*______Mono.thenReturn ⇢ at io.r2dbc.pool.ConnectionPool.getValidConnection(ConnectionPool.java:176)
|_ Mono.onErrorResume ⇢ at io.r2dbc.pool.ConnectionPool.lambda$null$5(ConnectionPool.java:140)
*____________Mono.then ⇢ at io.r2dbc.pool.ConnectionPool.lambda$null$3(ConnectionPool.java:140)
*_________Mono.flatMap ⇢ at io.r2dbc.pool.ConnectionPool.lambda$new$12(ConnectionPool.java:115)
*___________Mono.defer ⇢ at io.r2dbc.pool.ConnectionPool.<init>(ConnectionPool.java:112)
|_ Mono.retry ⇢ at io.r2dbc.pool.ConnectionPool.<init>(ConnectionPool.java:172)
*_______Mono.usingWhen ⇢ at org.springframework.boot.actuate.r2dbc.ConnectionFactoryHealthIndicator.validateWithConnectionValidation(ConnectionFactoryHealthIndicator.java:95)
|_ Mono.map ⇢ at org.springframework.boot.actuate.r2dbc.ConnectionFactoryHealthIndicator.validateWithConnectionValidation(ConnectionFactoryHealthIndicator.java:98)
|_ Mono.defaultIfEmpty ⇢ at org.springframework.boot.actuate.r2dbc.ConnectionFactoryHealthIndicator.doHealthCheck(ConnectionFactoryHealthIndicator.java:73)
Original Stack Trace:
at io.r2dbc.pool.Validation.lambda$validate$2(Validation.java:45) ~[r2dbc-pool-1.0.1.RELEASE.jar:1.0.1.RELEASE]
at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onNext(FluxHandleFuseable.java:179) ~[reactor-core-3.5.11.jar:3.5.11]
at reactor.core.publisher.MonoSupplier$MonoSupplierSubscription.request(MonoSupplier.java:145) ~[reactor-core-3.5.11.jar:3.5.11]
at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.request(FluxHandleFuseable.java:260) ~[reactor-core-3.5.11.jar:3.5.11]
at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onSubscribe(MonoIgnoreElements.java:72) ~[reactor-core-3.5.11.jar:3.5.11]
at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onSubscribe(FluxHandleFuseable.java:164) ~[reactor-core-3.5.11.jar:3.5.11]
at reactor.core.publisher.MonoSupplier.subscribe(MonoSupplier.java:48) ~[reactor-core-3.5.11.jar:3.5.11]
at reactor.core.publisher.Mono.subscribe(Mono.java:4495) ~[reactor-core-3.5.11.jar:3.5.11]
at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:263) ~[reactor-core-3.5.11.jar:3.5.11]
at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:51) ~[reactor-core-3.5.11.jar:3.5.11]
at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) ~[reactor-core-3.5.11.jar:3.5.11]
at io.r2dbc.pool.MonoDiscardOnCancel.subscribe(MonoDiscardOnCancel.java:50) ~[r2dbc-pool-1.0.1.RELEASE.jar:1.0.1.RELEASE]
at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:165) ~[reactor-core-3.5.11.jar:3.5.11]
at reactor.pool.AbstractPool$Borrower.deliver(AbstractPool.java:467) ~[reactor-pool-1.0.3.jar:1.0.3]
at reactor.pool.SimpleDequePool.lambda$drainLoop$9(SimpleDequePool.java:425) ~[reactor-pool-1.0.3.jar:1.0.3]
at reactor.core.publisher.FluxDoOnEach$DoOnEachSubscriber.onNext(FluxDoOnEach.java:154) ~[reactor-core-3.5.11.jar:3.5.11]
at reactor.core.publisher.FluxDoOnEach$DoOnEachFuseableSubscriber.onNext(FluxDoOnEach.java:281) ~[reactor-core-3.5.11.jar:3.5.11]
at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.onNext(MonoSubscribeOn.java:146) ~[reactor-core-3.5.11.jar:3.5.11]
at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2545) ~[reactor-core-3.5.11.jar:3.5.11]
at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.trySchedule(MonoSubscribeOn.java:189) ~[reactor-core-3.5.11.jar:3.5.11]
at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.onSubscribe(MonoSubscribeOn.java:134) ~[reactor-core-3.5.11.jar:3.5.11]
at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:55) ~[reactor-core-3.5.11.jar:3.5.11]
at reactor.core.publisher.Mono.subscribe(Mono.java:4495) ~[reactor-core-3.5.11.jar:3.5.11]
at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.run(MonoSubscribeOn.java:126) ~[reactor-core-3.5.11.jar:3.5.11]
at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:84) ~[reactor-core-3.5.11.jar:3.5.11]
at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:37) ~[reactor-core-3.5.11.jar:3.5.11]
at java.base/java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:317) ~[na:na]
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java) ~[na:na]
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) ~[na:na]
at java.base/java.lang.Thread.run(Thread.java:1583) ~[na:na]