search

GoogleCloudPlatform / cloud-spanner-r2dbc

R2DBC driver for Google Cloud Spanner
Apache License 2.0
57 stars 29 forks source link

r2dbc pool background eviction causes DatabaseClientReactiveAdapter to close #789

Open DasAmpharos opened 5 months ago

DasAmpharos commented 5 months ago

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]
mmastika commented 1 month ago

Hello, Do we have a plan or ETA for this to be fixed?