search

r2dbc / r2dbc-pool

Connection Pooling for Reactive Relational Database Connectivity
https://r2dbc.io
Apache License 2.0
331 stars 55 forks source link

R2dbcNonTransientResourceException after pool is idle #189

Closed jbrwn closed 1 year ago

jbrwn commented 1 year ago

Bug Report

Unsure if this its buggy behavior or just a configuration issue but I am getting a io.r2dbc.spi.R2dbcNonTransientResourceException: Connection validation failed exception if the pool is idle for more than a few minutes.

Versions

Current Behavior

If my web app is idle for more than a ~2 minutes I end up getting a io.r2dbc.spi.R2dbcNonTransientResourceException: Connection validation failed on the next request. Kind of hard to figure out exactly what is going on as i can't produce locally :(. This only happens when i deploy my app to fly.io. My app is a fly.io v1 app and the postgres DB is fly.io postgres DB.

Stack trace ``` 2023-03-18T00:52:32.178 app[048eed1f] den [info] 2023-03-18 00:52:32.176 [eventLoopGroupProxy-7-1] ERROR Application - Unhandled: GET - /dashboard 2023-03-18T00:52:32.178 app[048eed1f] den [info] java.lang.reflect.InvocationTargetException: null 2023-03-18T00:52:32.178 app[048eed1f] den [info] at jdk.internal.reflect.GeneratedMethodAccessor15.invoke(Unknown Source) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at java.base/java.lang.reflect.Method.invoke(Method.java:568) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at kotlin.reflect.jvm.internal.calls.CallerImpl$Method.callMethod(CallerImpl.kt:97) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at kotlin.reflect.jvm.internal.calls.CallerImpl$Method$Instance.call(CallerImpl.kt:113) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at kotlin.reflect.jvm.internal.KCallableImpl.call(KCallableImpl.kt:108) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at kotlin.reflect.jvm.internal.KCallableImpl.callDefaultMethod$kotlin_reflection(KCallableImpl.kt:159) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at kotlin.reflect.full.KCallables.callSuspendBy(KCallables.kt:74) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at dog.catfood.plugins.controllers.RouteProcessor.handleRoute(Controllers.kt:147) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at dog.catfood.plugins.controllers.RouteProcessor.access$handleRoute(Controllers.kt:121) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at dog.catfood.plugins.controllers.RouteProcessor$createRoute$1$1.invokeSuspend(Controllers.kt:126) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at dog.catfood.plugins.controllers.RouteProcessor$createRoute$1$1.invoke(Controllers.kt) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at dog.catfood.plugins.controllers.RouteProcessor$createRoute$1$1.invoke(Controllers.kt) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at io.ktor.server.routing.Route$buildPipeline$1$1.invokeSuspend(Route.kt:116) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at io.ktor.server.routing.Route$buildPipeline$1$1.invoke(Route.kt) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at io.ktor.server.routing.Route$buildPipeline$1$1.invoke(Route.kt) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at io.ktor.util.pipeline.SuspendFunctionGun.loop(SuspendFunctionGun.kt:120) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at io.ktor.util.pipeline.SuspendFunctionGun.access$loop(SuspendFunctionGun.kt:11) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at io.ktor.util.pipeline.SuspendFunctionGun$continuation$1.resumeWith(SuspendFunctionGun.kt:59) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:403) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at io.ktor.server.netty.EventLoopGroupProxy$Companion.create$lambda$1$lambda$0(NettyApplicationEngine.kt:291) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at java.base/java.lang.Thread.run(Thread.java:831) 2023-03-18T00:52:32.178 app[048eed1f] den [info] Caused by: org.jooq.exception.DataAccessException: SQL [TransactionSubscription]; Connection validation failed 2023-03-18T00:52:32.178 app[048eed1f] den [info] at org.jooq.impl.Tools.translate(Tools.java:3303) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at org.jooq.impl.Tools.translate(Tools.java:3287) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at org.jooq.impl.R2DBC$ConnectionSubscriber.onError(R2DBC.java:384) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at org.jooq.impl.Internal$1.onError(Internal.java:459) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.StrictSubscriber.onError(StrictSubscriber.java:106) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.FluxRetry$RetrySubscriber.onError(FluxRetry.java:95) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:241) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:315) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at io.r2dbc.pool.MonoDiscardOnCancel$MonoDiscardOnCancelSubscriber.onError(MonoDiscardOnCancel.java:98) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:106) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onError(MonoIgnoreThen.java:278) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:231) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:203) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.onComplete(FluxDoFinally.java:128) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.onComplete(FluxDoFinally.java:128) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:209) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:238) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:203) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.FluxPeek$PeekSubscriber.onComplete(FluxPeek.java:260) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.Operators.complete(Operators.java:137) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:46) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.Mono.subscribe(Mono.java:4444) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:263) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:51) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.Mono.subscribe(Mono.java:4444) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:263) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:51) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.Mono.subscribe(Mono.java:4444) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onError(MonoIgnoreThen.java:278) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onError(MonoIgnoreElements.java:84) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onNext(FluxHandleFuseable.java:200) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoSupplier$MonoSupplierSubscription.request(MonoSupplier.java:145) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.request(FluxHandleFuseable.java:259) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onSubscribe(MonoIgnoreElements.java:72) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onSubscribe(FluxHandleFuseable.java:163) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoSupplier.subscribe(MonoSupplier.java:48) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.Mono.subscribe(Mono.java:4444) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:263) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:51) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at io.r2dbc.pool.MonoDiscardOnCancel.subscribe(MonoDiscardOnCancel.java:50) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:165) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.pool.AbstractPool$Borrower.deliver(AbstractPool.java:467) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.pool.SimpleDequePool.lambda$drainLoop$8(SimpleDequePool.java:368) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.scheduler.ImmediateScheduler.schedule(ImmediateScheduler.java:52) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.pool.SimpleDequePool.drainLoop(SimpleDequePool.java:368) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.pool.SimpleDequePool.pendingOffer(SimpleDequePool.java:598) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.pool.SimpleDequePool.doAcquire(SimpleDequePool.java:294) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.pool.AbstractPool$Borrower.request(AbstractPool.java:430) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoFlatMap$FlatMapMain.request(MonoFlatMap.java:194) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:2304) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:2178) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoFlatMap$FlatMapMain.onSubscribe(MonoFlatMap.java:117) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.pool.SimpleDequePool$QueueBorrowerMono.subscribe(SimpleDequePool.java:716) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.FluxRetry$RetrySubscriber.resubscribe(FluxRetry.java:117) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.MonoRetry.subscribeOrReturn(MonoRetry.java:50) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.Mono.subscribe(Mono.java:4429) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at org.jooq.impl.R2DBC$AbstractNonBlockingSubscription.request0(R2DBC.java:565) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at org.jooq.impl.ThreadGuard.lambda$run$0(ThreadGuard.java:74) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at org.jooq.impl.ThreadGuard.run(ThreadGuard.java:87) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at org.jooq.impl.ThreadGuard.run(ThreadGuard.java:74) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at org.jooq.impl.R2DBC$AbstractSubscription.request(R2DBC.java:182) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt$awaitOne$2$1$onSubscribe$3.invoke(Await.kt:213) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt$awaitOne$2$1$onSubscribe$3.invoke(Await.kt:212) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt$awaitOne$2$1.withSubscriptionLock(Await.kt:310) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt$awaitOne$2$1.onSubscribe(Await.kt:212) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at org.jooq.impl.DefaultDSLContext.lambda$transactionPublisher$10(DefaultDSLContext.java:657) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt.awaitOne(Await.kt:190) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt.awaitOne$default(Await.kt:183) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt.awaitFirstOrNull(Await.kt:45) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at org.jooq.kotlin.coroutines.CoroutineExtensionsKt.transactionCoroutine(CoroutineExtensions.kt:18) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at dog.catfood.dao.DeviceDao.getDevices(DeviceDao.kt:42) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at dog.catfood.logic.DeviceService.getDevices(DeviceService.kt:11) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at dog.catfood.controllers.DashboardController.index(DashboardController.kt:19) 2023-03-18T00:52:32.178 app[048eed1f] den [info] ... 30 common frames omitted 2023-03-18T00:52:32.178 app[048eed1f] den [info] Caused by: io.r2dbc.spi.R2dbcNonTransientResourceException: Connection validation failed 2023-03-18T00:52:32.178 app[048eed1f] den [info] at io.r2dbc.pool.Validation.lambda$validate$2(Validation.java:45) 2023-03-18T00:52:32.178 app[048eed1f] den [info] at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onNext(FluxHandleFuseable.java:178) 2023-03-18T00:52:32.178 app[048eed1f] den [info] ... 75 common frames omitted 2023-03-18T00:52:32.179 app[048eed1f] den [info] 2023-03-18 00:52:32.178 [eventLoopGroupProxy-7-1] INFO Application - 500 Internal Server Error: GET - /dashboard in 15ms 2023-03-18T00:52:33.097 app[048eed1f] den [info] 2023-03-18 00:52:33.092 [eventLoopGroupProxy-7-1] ERROR Application - Unhandled: GET - /dashboard 2023-03-18T00:52:33.097 app[048eed1f] den [info] java.lang.reflect.InvocationTargetException: null 2023-03-18T00:52:33.097 app[048eed1f] den [info] at jdk.internal.reflect.GeneratedMethodAccessor15.invoke(Unknown Source) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at java.base/java.lang.reflect.Method.invoke(Method.java:568) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at kotlin.reflect.jvm.internal.calls.CallerImpl$Method.callMethod(CallerImpl.kt:97) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at kotlin.reflect.jvm.internal.calls.CallerImpl$Method$Instance.call(CallerImpl.kt:113) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at kotlin.reflect.jvm.internal.KCallableImpl.call(KCallableImpl.kt:108) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at kotlin.reflect.jvm.internal.KCallableImpl.callDefaultMethod$kotlin_reflection(KCallableImpl.kt:159) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at kotlin.reflect.full.KCallables.callSuspendBy(KCallables.kt:74) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at dog.catfood.plugins.controllers.RouteProcessor.handleRoute(Controllers.kt:147) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at dog.catfood.plugins.controllers.RouteProcessor.access$handleRoute(Controllers.kt:121) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at dog.catfood.plugins.controllers.RouteProcessor$createRoute$1$1.invokeSuspend(Controllers.kt:126) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at dog.catfood.plugins.controllers.RouteProcessor$createRoute$1$1.invoke(Controllers.kt) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at dog.catfood.plugins.controllers.RouteProcessor$createRoute$1$1.invoke(Controllers.kt) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at io.ktor.server.routing.Route$buildPipeline$1$1.invokeSuspend(Route.kt:116) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at io.ktor.server.routing.Route$buildPipeline$1$1.invoke(Route.kt) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at io.ktor.server.routing.Route$buildPipeline$1$1.invoke(Route.kt) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at io.ktor.util.pipeline.SuspendFunctionGun.loop(SuspendFunctionGun.kt:120) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at io.ktor.util.pipeline.SuspendFunctionGun.access$loop(SuspendFunctionGun.kt:11) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at io.ktor.util.pipeline.SuspendFunctionGun$continuation$1.resumeWith(SuspendFunctionGun.kt:59) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:403) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at io.ktor.server.netty.EventLoopGroupProxy$Companion.create$lambda$1$lambda$0(NettyApplicationEngine.kt:291) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at java.base/java.lang.Thread.run(Thread.java:831) 2023-03-18T00:52:33.097 app[048eed1f] den [info] Caused by: org.jooq.exception.DataAccessException: SQL [TransactionSubscription]; Connection validation failed 2023-03-18T00:52:33.097 app[048eed1f] den [info] at org.jooq.impl.Tools.translate(Tools.java:3303) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at org.jooq.impl.Tools.translate(Tools.java:3287) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at org.jooq.impl.R2DBC$ConnectionSubscriber.onError(R2DBC.java:384) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at org.jooq.impl.Internal$1.onError(Internal.java:459) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.StrictSubscriber.onError(StrictSubscriber.java:106) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.FluxRetry$RetrySubscriber.onError(FluxRetry.java:95) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:241) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:315) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at io.r2dbc.pool.MonoDiscardOnCancel$MonoDiscardOnCancelSubscriber.onError(MonoDiscardOnCancel.java:98) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:106) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onError(MonoIgnoreThen.java:278) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:231) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:203) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.onComplete(FluxDoFinally.java:128) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.onComplete(FluxDoFinally.java:128) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:209) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:238) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:203) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.FluxPeek$PeekSubscriber.onComplete(FluxPeek.java:260) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.Operators.complete(Operators.java:137) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:46) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.Mono.subscribe(Mono.java:4444) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:263) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:51) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.Mono.subscribe(Mono.java:4444) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:263) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:51) 2023-03-18T00:52:33.097 app[048eed1f] den [info] at reactor.core.publisher.Mono.subscribe(Mono.java:4444) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onError(MonoIgnoreThen.java:278) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onError(MonoIgnoreElements.java:84) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onNext(FluxHandleFuseable.java:200) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.MonoSupplier$MonoSupplierSubscription.request(MonoSupplier.java:145) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.request(FluxHandleFuseable.java:259) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onSubscribe(MonoIgnoreElements.java:72) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onSubscribe(FluxHandleFuseable.java:163) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.MonoSupplier.subscribe(MonoSupplier.java:48) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.Mono.subscribe(Mono.java:4444) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:263) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:51) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at io.r2dbc.pool.MonoDiscardOnCancel.subscribe(MonoDiscardOnCancel.java:50) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:165) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.pool.AbstractPool$Borrower.deliver(AbstractPool.java:467) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.pool.SimpleDequePool.lambda$drainLoop$8(SimpleDequePool.java:368) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.scheduler.ImmediateScheduler.schedule(ImmediateScheduler.java:52) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.pool.SimpleDequePool.drainLoop(SimpleDequePool.java:368) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.pool.SimpleDequePool.pendingOffer(SimpleDequePool.java:598) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.pool.SimpleDequePool.doAcquire(SimpleDequePool.java:294) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.pool.AbstractPool$Borrower.request(AbstractPool.java:430) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.MonoFlatMap$FlatMapMain.request(MonoFlatMap.java:194) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:2304) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:2178) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.MonoFlatMap$FlatMapMain.onSubscribe(MonoFlatMap.java:117) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.pool.SimpleDequePool$QueueBorrowerMono.subscribe(SimpleDequePool.java:716) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.FluxRetry$RetrySubscriber.resubscribe(FluxRetry.java:117) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.MonoRetry.subscribeOrReturn(MonoRetry.java:50) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.Mono.subscribe(Mono.java:4429) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at org.jooq.impl.R2DBC$AbstractNonBlockingSubscription.request0(R2DBC.java:565) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at org.jooq.impl.ThreadGuard.lambda$run$0(ThreadGuard.java:74) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at org.jooq.impl.ThreadGuard.run(ThreadGuard.java:87) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at org.jooq.impl.ThreadGuard.run(ThreadGuard.java:74) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at org.jooq.impl.R2DBC$AbstractSubscription.request(R2DBC.java:182) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt$awaitOne$2$1$onSubscribe$3.invoke(Await.kt:213) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt$awaitOne$2$1$onSubscribe$3.invoke(Await.kt:212) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt$awaitOne$2$1.withSubscriptionLock(Await.kt:310) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt$awaitOne$2$1.onSubscribe(Await.kt:212) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at org.jooq.impl.DefaultDSLContext.lambda$transactionPublisher$10(DefaultDSLContext.java:657) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt.awaitOne(Await.kt:190) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt.awaitOne$default(Await.kt:183) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt.awaitFirstOrNull(Await.kt:45) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at org.jooq.kotlin.coroutines.CoroutineExtensionsKt.transactionCoroutine(CoroutineExtensions.kt:18) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at dog.catfood.dao.DeviceDao.getDevices(DeviceDao.kt:42) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at dog.catfood.logic.DeviceService.getDevices(DeviceService.kt:11) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at dog.catfood.controllers.DashboardController.index(DashboardController.kt:19) 2023-03-18T00:52:33.098 app[048eed1f] den [info] ... 30 common frames omitted 2023-03-18T00:52:33.098 app[048eed1f] den [info] Caused by: io.r2dbc.spi.R2dbcNonTransientResourceException: Connection validation failed 2023-03-18T00:52:33.098 app[048eed1f] den [info] at io.r2dbc.pool.Validation.lambda$validate$2(Validation.java:45) 2023-03-18T00:52:33.098 app[048eed1f] den [info] at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onNext(FluxHandleFuseable.java:178) 2023-03-18T00:52:33.098 app[048eed1f] den [info] ... 75 common frames omitted 2023-03-18T00:52:33.098 app[048eed1f] den [info] 2023-03-18 00:52:33.097 [eventLoopGroupProxy-7-1] INFO Application - 500 Internal Server Error: GET - /dashboard in 27ms 2023-03-18T00:52:34.079 app[048eed1f] den [info] 2023-03-18 00:52:34.078 [eventLoopGroupProxy-7-1] INFO Application - 200 OK: GET - /dashboard in 90ms 2023-03-18T00:52:34.227 app[048eed1f] den [info] 2023-03-18 00:52:34.226 [eventLoopGroupProxy-7-1] INFO Application - 200 OK: GET - /assets/css/pico.min.css in 7ms 2023-03-18T00:52:34.228 app[048eed1f] den [info] 2023-03-18 00:52:34.227 [eventLoopGroupProxy-7-1] INFO Application - 200 OK: GET - /assets/css/custom.css in 0ms 2023-03-18T00:53:11.444 app[048eed1f] den [info] 2023-03-18 00:53:11.444 [eventLoopGroupProxy-7-1] INFO Application - 200 OK: GET - /dashboard in 71ms 2023-03-18T00:53:11.576 app[048eed1f] den [info] 2023-03-18 00:53:11.575 [eventLoopGroupProxy-7-1] INFO Application - 200 OK: GET - /assets/css/pico.min.css in 3ms 2023-03-18T00:53:11.586 app[048eed1f] den [info] 2023-03-18 00:53:11.585 [eventLoopGroupProxy-7-1] INFO Application - 200 OK: GET - /assets/css/custom.css in 8ms 2023-03-18T00:54:10.251 app[048eed1f] den [info] 2023-03-18 00:54:10.250 [eventLoopGroupProxy-7-1] INFO Application - 200 OK: GET - /dashboard in 56ms 2023-03-18T00:54:10.393 app[048eed1f] den [info] 2023-03-18 00:54:10.392 [eventLoopGroupProxy-7-1] INFO Application - 200 OK: GET - /assets/css/pico.min.css in 9ms 2023-03-18T00:54:10.395 app[048eed1f] den [info] 2023-03-18 00:54:10.395 [eventLoopGroupProxy-7-1] INFO Application - 200 OK: GET - /assets/css/custom.css in 2ms 2023-03-18T00:54:25.587 app[048eed1f] den [info] 2023-03-18 00:54:25.586 [eventLoopGroupProxy-7-1] INFO Application - 200 OK: GET - /dashboard in 52ms 2023-03-18T00:54:25.727 app[048eed1f] den [info] 2023-03-18 00:54:25.726 [eventLoopGroupProxy-7-1] INFO Application - 200 OK: GET - /assets/css/pico.min.css in 4ms 2023-03-18T00:54:25.735 app[048eed1f] den [info] 2023-03-18 00:54:25.735 [eventLoopGroupProxy-7-1] INFO Application - 200 OK: GET - /assets/css/custom.css in 2ms 2023-03-18T00:56:29.767 app[048eed1f] den [info] 2023-03-18 00:56:29.766 [eventLoopGroupProxy-7-1] ERROR Application - Unhandled: GET - /dashboard 2023-03-18T00:56:29.767 app[048eed1f] den [info] java.lang.reflect.InvocationTargetException: null 2023-03-18T00:56:29.767 app[048eed1f] den [info] at jdk.internal.reflect.GeneratedMethodAccessor15.invoke(Unknown Source) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at java.base/java.lang.reflect.Method.invoke(Method.java:568) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at kotlin.reflect.jvm.internal.calls.CallerImpl$Method.callMethod(CallerImpl.kt:97) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at kotlin.reflect.jvm.internal.calls.CallerImpl$Method$Instance.call(CallerImpl.kt:113) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at kotlin.reflect.jvm.internal.KCallableImpl.call(KCallableImpl.kt:108) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at kotlin.reflect.jvm.internal.KCallableImpl.callDefaultMethod$kotlin_reflection(KCallableImpl.kt:159) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at kotlin.reflect.full.KCallables.callSuspendBy(KCallables.kt:74) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at dog.catfood.plugins.controllers.RouteProcessor.handleRoute(Controllers.kt:147) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at dog.catfood.plugins.controllers.RouteProcessor.access$handleRoute(Controllers.kt:121) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at dog.catfood.plugins.controllers.RouteProcessor$createRoute$1$1.invokeSuspend(Controllers.kt:126) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at dog.catfood.plugins.controllers.RouteProcessor$createRoute$1$1.invoke(Controllers.kt) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at dog.catfood.plugins.controllers.RouteProcessor$createRoute$1$1.invoke(Controllers.kt) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at io.ktor.server.routing.Route$buildPipeline$1$1.invokeSuspend(Route.kt:116) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at io.ktor.server.routing.Route$buildPipeline$1$1.invoke(Route.kt) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at io.ktor.server.routing.Route$buildPipeline$1$1.invoke(Route.kt) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at io.ktor.util.pipeline.SuspendFunctionGun.loop(SuspendFunctionGun.kt:120) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at io.ktor.util.pipeline.SuspendFunctionGun.access$loop(SuspendFunctionGun.kt:11) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at io.ktor.util.pipeline.SuspendFunctionGun$continuation$1.resumeWith(SuspendFunctionGun.kt:59) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:403) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) 2023-03-18T00:56:29.767 app[048eed1f] den [info] at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at io.ktor.server.netty.EventLoopGroupProxy$Companion.create$lambda$1$lambda$0(NettyApplicationEngine.kt:291) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at java.base/java.lang.Thread.run(Thread.java:831) 2023-03-18T00:56:29.768 app[048eed1f] den [info] Caused by: org.jooq.exception.DataAccessException: SQL [TransactionSubscription]; Connection validation failed 2023-03-18T00:56:29.768 app[048eed1f] den [info] at org.jooq.impl.Tools.translate(Tools.java:3303) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at org.jooq.impl.Tools.translate(Tools.java:3287) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at org.jooq.impl.R2DBC$ConnectionSubscriber.onError(R2DBC.java:384) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at org.jooq.impl.Internal$1.onError(Internal.java:459) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.StrictSubscriber.onError(StrictSubscriber.java:106) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.FluxRetry$RetrySubscriber.onError(FluxRetry.java:95) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:241) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:315) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at io.r2dbc.pool.MonoDiscardOnCancel$MonoDiscardOnCancelSubscriber.onError(MonoDiscardOnCancel.java:98) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:106) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onError(MonoIgnoreThen.java:278) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:231) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:203) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.onComplete(FluxDoFinally.java:128) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.onComplete(FluxDoFinally.java:128) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:209) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:238) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:203) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.FluxPeek$PeekSubscriber.onComplete(FluxPeek.java:260) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.Operators.complete(Operators.java:137) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:46) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.Mono.subscribe(Mono.java:4444) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:263) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:51) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.Mono.subscribe(Mono.java:4444) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:263) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:51) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.Mono.subscribe(Mono.java:4444) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onError(MonoIgnoreThen.java:278) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onError(MonoIgnoreElements.java:84) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onNext(FluxHandleFuseable.java:200) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoSupplier$MonoSupplierSubscription.request(MonoSupplier.java:145) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.request(FluxHandleFuseable.java:259) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onSubscribe(MonoIgnoreElements.java:72) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onSubscribe(FluxHandleFuseable.java:163) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoSupplier.subscribe(MonoSupplier.java:48) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.Mono.subscribe(Mono.java:4444) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:263) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:51) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at io.r2dbc.pool.MonoDiscardOnCancel.subscribe(MonoDiscardOnCancel.java:50) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:165) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.pool.AbstractPool$Borrower.deliver(AbstractPool.java:467) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.pool.SimpleDequePool.lambda$drainLoop$8(SimpleDequePool.java:368) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.scheduler.ImmediateScheduler.schedule(ImmediateScheduler.java:52) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.pool.SimpleDequePool.drainLoop(SimpleDequePool.java:368) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.pool.SimpleDequePool.pendingOffer(SimpleDequePool.java:598) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.pool.SimpleDequePool.doAcquire(SimpleDequePool.java:294) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.pool.AbstractPool$Borrower.request(AbstractPool.java:430) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoFlatMap$FlatMapMain.request(MonoFlatMap.java:194) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:2304) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:2178) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoFlatMap$FlatMapMain.onSubscribe(MonoFlatMap.java:117) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.pool.SimpleDequePool$QueueBorrowerMono.subscribe(SimpleDequePool.java:716) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.FluxRetry$RetrySubscriber.resubscribe(FluxRetry.java:117) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.MonoRetry.subscribeOrReturn(MonoRetry.java:50) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at reactor.core.publisher.Mono.subscribe(Mono.java:4429) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at org.jooq.impl.R2DBC$AbstractNonBlockingSubscription.request0(R2DBC.java:565) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at org.jooq.impl.ThreadGuard.lambda$run$0(ThreadGuard.java:74) 2023-03-18T00:56:29.768 app[048eed1f] den [info] at org.jooq.impl.ThreadGuard.run(ThreadGuard.java:87) 2023-03-18T00:56:29.773 app[048eed1f] den [info] at org.jooq.impl.ThreadGuard.run(ThreadGuard.java:74) 2023-03-18T00:56:29.773 app[048eed1f] den [info] at org.jooq.impl.R2DBC$AbstractSubscription.request(R2DBC.java:182) 2023-03-18T00:56:29.773 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt$awaitOne$2$1$onSubscribe$3.invoke(Await.kt:213) 2023-03-18T00:56:29.773 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt$awaitOne$2$1$onSubscribe$3.invoke(Await.kt:212) 2023-03-18T00:56:29.773 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt$awaitOne$2$1.withSubscriptionLock(Await.kt:310) 2023-03-18T00:56:29.773 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt$awaitOne$2$1.onSubscribe(Await.kt:212) 2023-03-18T00:56:29.773 app[048eed1f] den [info] at org.jooq.impl.DefaultDSLContext.lambda$transactionPublisher$10(DefaultDSLContext.java:657) 2023-03-18T00:56:29.773 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt.awaitOne(Await.kt:190) 2023-03-18T00:56:29.773 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt.awaitOne$default(Await.kt:183) 2023-03-18T00:56:29.773 app[048eed1f] den [info] at kotlinx.coroutines.reactive.AwaitKt.awaitFirstOrNull(Await.kt:45) 2023-03-18T00:56:29.773 app[048eed1f] den [info] at org.jooq.kotlin.coroutines.CoroutineExtensionsKt.transactionCoroutine(CoroutineExtensions.kt:18) 2023-03-18T00:56:29.773 app[048eed1f] den [info] at dog.catfood.dao.DeviceDao.getDevices(DeviceDao.kt:42) 2023-03-18T00:56:29.773 app[048eed1f] den [info] at dog.catfood.logic.DeviceService.getDevices(DeviceService.kt:11) 2023-03-18T00:56:29.773 app[048eed1f] den [info] at dog.catfood.controllers.DashboardController.index(DashboardController.kt:19) 2023-03-18T00:56:29.773 app[048eed1f] den [info] ... 30 common frames omitted 2023-03-18T00:56:29.773 app[048eed1f] den [info] Caused by: io.r2dbc.spi.R2dbcNonTransientResourceException: Connection validation failed 2023-03-18T00:56:29.773 app[048eed1f] den [info] at io.r2dbc.pool.Validation.lambda$validate$2(Validation.java:45) 2023-03-18T00:56:29.773 app[048eed1f] den [info] at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onNext(FluxHandleFuseable.java:178) 2023-03-18T00:56:29.773 app[048eed1f] den [info] ... 75 common frames omitted 2023-03-18T00:56:29.774 app[048eed1f] den [info] 2023-03-18 00:56:29.773 [eventLoopGroupProxy-7-1] INFO Application - 500 Internal Server Error: GET - /dashboard in 22ms ```

Table schema

Input Code ```sql -- your SQL here; ```

Steps to reproduce

Input Code ```java // your code here; ```

Expected behavior/code

Possible Solution

Additional context

I am using r2dbc with ktor and jooq.

My pool configuration is pretty straightforward. Basically just using the default:

    val connectionFactory: ConnectionFactory = ConnectionFactories.get(
        ConnectionFactoryOptions.builder()
            .option(DRIVER,"pool")
            .option(PROTOCOL,"postgresql")
            .option(HOST, config["db.host"])
            .option(PORT, config["db.port"])
            .option(USER, config["db.user"])
            .option(PASSWORD, config["db.password"])
            .option(DATABASE, config["db.name"])
            .build()
    )
mp911de commented 1 year ago

Connection validation is subject to the underlying driver. With the default allocation strategy, the pool retries acquisition of a connection one more time. If the subsequent connection validation also fails, you get to see the exception.

I think that a lot of connections within your pool are closed. You can configure the retry by setting the acquireRetry property. Depending on your infrastructure, you might to check why these are closed.