r2dbc / r2dbc-pool

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

R2dbcNonTransientResourceException: Connection validation failed #209

Open menakaprabu opened 3 months ago

menakaprabu commented 3 months ago

Hi, I am getting this issue "org.springframework.dao.DataAccessResourceFailureException: Failed to obtain R2DBC Connection nested exception. Caused by io.r2dbc.spi.R2dbcNonTransientResourceException: Connection validation failed" in MSSQL. I am using below libraries(Version).

io.r2dbc r2dbc-pool 1.0.0.RELEASE
    <dependency>
        <groupId>io.r2dbc</groupId>
        <artifactId>r2dbc-mssql</artifactId>
        <version>1.0.0.RELEASE</version>
    </dependency>

I am seeing this issue in both pre-prod and production environment intermittently. Could you please help me with this? Thanks.

mp911de commented 3 months ago

Is there more to the stack trace? Typically, the cause shows the reason for the validation failure.

menakaprabu commented 3 months ago

Hi Mark,

Thanks for the response. Here are more logs.

at io.r2dbc.pool.Validation.lambda$validate$2(Validation.java:45) ~[r2dbc-pool-1.0.0.RELEASE.jar!/:1.0.0.RELEASE]","" "4/9/2024, 3:57:10.276 PM","Caused by: io.r2dbc.spi.R2dbcNonTransientResourceException: Connection validation failed","" .... .... at org.springframework.r2dbc.connection.ConnectionFactoryUtils.lambda$getConnection$0(ConnectionFactoryUtils.java:100) ~[spring-r2dbc-6.1.1.jar!/:6.1.1]","" "Caused by: org.springframework.dao.DataAccessResourceFailureException: Failed to obtain R2DBC Connection",""

reactor.core.Exceptions$ErrorCallbackNotImplemented: org.springframework.dao.DataAccessResourceFailureException: Failed to obtain R2DBC Connection",""

Thanks

On Tue, Apr 9, 2024 at 1:08 AM Mark Paluch @.***> wrote:

Is there more to the stack trace? Typically, the cause shows the reason for the validation failure.

— Reply to this email directly, view it on GitHub https://github.com/r2dbc/r2dbc-pool/issues/209#issuecomment-2044395247, or unsubscribe https://github.com/notifications/unsubscribe-auth/AJIZE6JWBHGUXLQVXSKATFTY4OOWRAVCNFSM6AAAAABFZULG2WVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDANBUGM4TKMRUG4 . You are receiving this because you authored the thread.Message ID: @.***>

MBecM commented 3 months ago

Maybe I will add more information, because I'm fighting with the same problem for the last couple of days.

Versions

Stacktrace

io.r2dbc.spi.R2dbcNonTransientResourceException: Connection validation failed
  at io.r2dbc.pool.Validation.lambda$validate$2(Validation.java:45)
  at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onNext(FluxHandleFuseable.java:179)
  at reactor.core.publisher.MonoSupplier$MonoSupplierSubscription.request(MonoSupplier.java:145)
  at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.request(FluxHandleFuseable.java:260)
  at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onSubscribe(MonoIgnoreElements.java:72)
  at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onSubscribe(FluxHandleFuseable.java:164)
  at reactor.core.publisher.MonoSupplier.subscribe(MonoSupplier.java:48)

Pool configuration

default

Additional context

This issue happens in my case 2-3 times a day in different day time. It is totally random when will it happen. What is more interesting, that after some time (10-20sec) everything goes back to normal work. So it "heals" itself, but during this 10-20sec non of my queries are executed. During my investigation I found that validation is performed 2 times.

  1. During connectionFactory.create() https://github.com/r2dbc/r2dbc-pool/blob/3ee034a65e888e0e3fcb330777afc3715ced6797/src/main/java/io/r2dbc/pool/ConnectionPool.java#L135
  2. After query during connectionFactory.close() https://github.com/r2dbc/r2dbc-pool/blob/3ee034a65e888e0e3fcb330777afc3715ced6797/src/main/java/io/r2dbc/pool/PooledConnection.java#L66

In my case it happens only on 1 case, that's why query is not executed, because connection is not acquired from connection pool. Stacktrace is also not very helpful, because it points only to 45 line in Validation.class https://github.com/r2dbc/r2dbc-pool/blob/3ee034a65e888e0e3fcb330777afc3715ced6797/src/main/java/io/r2dbc/pool/Validation.java#L45

Steps to reproduce

Restart database server between queries.

  1. Start application
  2. Execute query
  3. Restart database server: sudo pg_ctl restart / Ubuntu: sudo pg_ctlcluster 14 main restart
  4. Execute query (should FAIL with provided stacktrace)

Related issues

#138 #107

Possible Solution The only way to mitigate this problem I found was to increase default acquireRetry property from 1 to 10, which is maxSize value.

In that case the following Mono<Connection> create will retry until it find valid connection. https://github.com/r2dbc/r2dbc-pool/blob/3ee034a65e888e0e3fcb330777afc3715ced6797/src/main/java/io/r2dbc/pool/ConnectionPool.java#L172

But I'm afraid that this only hides/delays the problem and makes it even more unpredictable. @mp911de correct me if I'm wrong. With my solution, connection pool will try 10 times to acquire connection until it founds valid connection, so basically "searches" through entire pool to find what it needs. I assume that if none of connection is valid then this exception would be fired.

menakaprabu commented 3 months ago

Here is my configuration. poolInitialSize=10 poolMaxSize=30 maxIdleTime=60 mins (1hr)

-Thanks

On Wed, Apr 10, 2024 at 12:26 AM MBec @.***> wrote:

Maybe I will add more information, because I'm fighting with the same problem for the last couple of days.

Versions

  • Driver: r2dbc-postgres
  • Database: postgres
  • Java: 21
  • io.r2dbc:r2dbc-spi:1.0.0.RELEASE
  • io.r2dbc:r2dbc-pool:1.0.1.RELEASE

Stacktrace

io.r2dbc.spi.R2dbcNonTransientResourceException: Connection validation failed at io.r2dbc.pool.Validation.lambda$validate$2(Validation.java:45) at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onNext(FluxHandleFuseable.java:179) at reactor.core.publisher.MonoSupplier$MonoSupplierSubscription.request(MonoSupplier.java:145) at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.request(FluxHandleFuseable.java:260) at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onSubscribe(MonoIgnoreElements.java:72) at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onSubscribe(FluxHandleFuseable.java:164) at reactor.core.publisher.MonoSupplier.subscribe(MonoSupplier.java:48)

Pool configuration

default

Additional context

This issue happens in my case 2-3 times a day in different day time. It is totally random when will it happen. What is more interesting, that after some time (10-20sec) everything goes back to normal work. So it "heals" itself, but during this 10-20sec non of my queries are executed. During my investigation I found that validation is performed 2 times.

  1. During connectionFactory.create()

    https://github.com/r2dbc/r2dbc-pool/blob/3ee034a65e888e0e3fcb330777afc3715ced6797/src/main/java/io/r2dbc/pool/ConnectionPool.java#L135

  2. After query during connectionFactory.close()

    https://github.com/r2dbc/r2dbc-pool/blob/3ee034a65e888e0e3fcb330777afc3715ced6797/src/main/java/io/r2dbc/pool/PooledConnection.java#L66

In my case it happens only on 1 case, that's why query is not executed, because connection is not acquired from connection pool. Stacktrace is also not very helpful, because it points only to 45 line in Validation.class

https://github.com/r2dbc/r2dbc-pool/blob/3ee034a65e888e0e3fcb330777afc3715ced6797/src/main/java/io/r2dbc/pool/Validation.java#L45

Steps to reproduce

Restart database server between queries.

  1. Start application
  2. Execute query
  3. Restart database server: sudo pg_ctl restart / Ubuntu: sudo pg_ctlcluster 14 main restart
  4. Execute query (should FAIL with provided stacktrace)

Related issues

138 https://github.com/r2dbc/r2dbc-pool/issues/138

107 https://github.com/r2dbc/r2dbc-pool/issues/107

Possible Solution The only way to mitigate this problem I found was to increase default acquireRetry property from 1 to 10, which is maxSize value.

In that case the following Mono create will retry until it find valid connection.

https://github.com/r2dbc/r2dbc-pool/blob/3ee034a65e888e0e3fcb330777afc3715ced6797/src/main/java/io/r2dbc/pool/ConnectionPool.java#L172

But I'm afraid that this only hides/delays the problem and makes it even more unpredictable. @mp911de https://github.com/mp911de correct me if I'm wrong. With my solution, connection pool will try 10 times to acquire connection until it founds valid connection, so basically "searches" through entire pool to find what it needs. I assume that if none of connection is valid then this exception would be fired.

Not related I'm not able to set pool.acquireRetry property in spring-data-r2dbc in application.yml. I had to create manual connection pool without R2dbcAutoConfiguration.class.

— Reply to this email directly, view it on GitHub https://github.com/r2dbc/r2dbc-pool/issues/209#issuecomment-2046713072, or unsubscribe https://github.com/notifications/unsubscribe-auth/AJIZE6IJA2RCFVFP2N76QRTY4TSRVAVCNFSM6AAAAABFZULG2WVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDANBWG4YTGMBXGI . You are receiving this because you authored the thread.Message ID: @.***>

menakaprabu commented 3 months ago

Hi @mp911de ,

Do you have any update for me. This issue is acting like a blocker, please let me know if you need more details from me. -Thanks.

menakaprabu commented 2 months ago

Hi Mark,

Any suggestion, I tried with maxIdle from 60 mins to 10 mins but still I see the issue. We are struggling with this issue in the production environment. Please help me in resolving this issue. -Thanks

On Wed, Apr 10, 2024 at 10:58 AM menaka prabu @.***> wrote:

Here is my configuration. poolInitialSize=10 poolMaxSize=30 maxIdleTime=60 mins (1hr)

-Thanks

On Wed, Apr 10, 2024 at 12:26 AM MBec @.***> wrote:

Maybe I will add more information, because I'm fighting with the same problem for the last couple of days.

Versions

  • Driver: r2dbc-postgres
  • Database: postgres
  • Java: 21
  • io.r2dbc:r2dbc-spi:1.0.0.RELEASE
  • io.r2dbc:r2dbc-pool:1.0.1.RELEASE

Stacktrace

io.r2dbc.spi.R2dbcNonTransientResourceException: Connection validation failed at io.r2dbc.pool.Validation.lambda$validate$2(Validation.java:45) at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onNext(FluxHandleFuseable.java:179) at reactor.core.publisher.MonoSupplier$MonoSupplierSubscription.request(MonoSupplier.java:145) at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.request(FluxHandleFuseable.java:260) at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onSubscribe(MonoIgnoreElements.java:72) at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onSubscribe(FluxHandleFuseable.java:164) at reactor.core.publisher.MonoSupplier.subscribe(MonoSupplier.java:48)

Pool configuration

default

Additional context

This issue happens in my case 2-3 times a day in different day time. It is totally random when will it happen. What is more interesting, that after some time (10-20sec) everything goes back to normal work. So it "heals" itself, but during this 10-20sec non of my queries are executed. During my investigation I found that validation is performed 2 times.

  1. During connectionFactory.create()

    https://github.com/r2dbc/r2dbc-pool/blob/3ee034a65e888e0e3fcb330777afc3715ced6797/src/main/java/io/r2dbc/pool/ConnectionPool.java#L135

  2. After query during connectionFactory.close()

    https://github.com/r2dbc/r2dbc-pool/blob/3ee034a65e888e0e3fcb330777afc3715ced6797/src/main/java/io/r2dbc/pool/PooledConnection.java#L66

In my case it happens only on 1 case, that's why query is not executed, because connection is not acquired from connection pool. Stacktrace is also not very helpful, because it points only to 45 line in Validation.class

https://github.com/r2dbc/r2dbc-pool/blob/3ee034a65e888e0e3fcb330777afc3715ced6797/src/main/java/io/r2dbc/pool/Validation.java#L45

Steps to reproduce

Restart database server between queries.

  1. Start application
  2. Execute query
  3. Restart database server: sudo pg_ctl restart / Ubuntu: sudo pg_ctlcluster 14 main restart
  4. Execute query (should FAIL with provided stacktrace)

Related issues

138 https://github.com/r2dbc/r2dbc-pool/issues/138

107 https://github.com/r2dbc/r2dbc-pool/issues/107

Possible Solution The only way to mitigate this problem I found was to increase default acquireRetry property from 1 to 10, which is maxSize value.

In that case the following Mono create will retry until it find valid connection.

https://github.com/r2dbc/r2dbc-pool/blob/3ee034a65e888e0e3fcb330777afc3715ced6797/src/main/java/io/r2dbc/pool/ConnectionPool.java#L172

But I'm afraid that this only hides/delays the problem and makes it even more unpredictable. @mp911de https://github.com/mp911de correct me if I'm wrong. With my solution, connection pool will try 10 times to acquire connection until it founds valid connection, so basically "searches" through entire pool to find what it needs. I assume that if none of connection is valid then this exception would be fired.

Not related I'm not able to set pool.acquireRetry property in spring-data-r2dbc in application.yml. I had to create manual connection pool without R2dbcAutoConfiguration.class.

— Reply to this email directly, view it on GitHub https://github.com/r2dbc/r2dbc-pool/issues/209#issuecomment-2046713072, or unsubscribe https://github.com/notifications/unsubscribe-auth/AJIZE6IJA2RCFVFP2N76QRTY4TSRVAVCNFSM6AAAAABFZULG2WVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDANBWG4YTGMBXGI . You are receiving this because you authored the thread.Message ID: @.***>

CennyMo commented 3 weeks ago

@MBecM we met same problem and decided to change max retryTimes to 10. It seems that when r2dbc pool get an invalid connection and validate query failed, the connection will be invalidated:

src/main/java/io/r2dbc/pool/ConnectionPool.java 140: conn = conn.onErrorResume(throwable -> ref.invalidate().then(Mono.error(throwable)));

So theoretically all the connections will recovery in the end. Have you encountered any other problems after changing it to 10?

CennyMo commented 3 weeks ago

@menakaprabu Under what circumstances would this issue be triggered in your scenario? Restart database or just suddenly break down when system running in long term?
We always met this problem when databases was crashed, and the fault will disappear as time and new requests increase. But if database is normal, considering set the maxLifeTime(Connection will never timeout when maxLifeTime is not configured) and test if it's useful. Cause it's possibly that sql server release the connection, however client still use it.

CennyMo commented 1 week ago

@menakaprabu Under what circumstances would this issue be triggered in your scenario? Restart database or just suddenly break down when system running in long term? We always met this problem when databases was crashed, and the fault will disappear as time and new requests increase. But if database is normal, considering set the maxLifeTime(Connection will never timeout when maxLifeTime is not configured) and test if it's useful. Cause it's possibly that sql server release the connection, however client still use it.

2024/07/08 update. We solve our problem by setting minIdle to 0.

menakaprabu commented 1 week ago

Hi @CennyMo , We are getting this issue when database is normal. We are having below config. poolInitialSize=10 poolMaxSize=30 maxIdleTime=60 mins (1hr) I don't have maxLifeTime and minIdle set.

CennyMo commented 1 week ago

Hi @CennyMo , We are getting this issue when database is normal. We are having below config. poolInitialSize=10 poolMaxSize=30 maxIdleTime=60 mins (1hr) I don't have maxLifeTime and minIdle set.

I suggest config maxLifeTime to 20min, or smaller, cause database server also has a "timeout" when it holds a connection established from client, in mysql(we use mysql now), it's 30min. You can check this config in MSSql too. The maxLifeTime config in client should always be smaller than the timeout config of database server.

As for maxIdleTime, in fact, the actual idleTime of connection is calculated by System.currentMills() - latest active timestamp, and the latest active timestamp of connection is refreshed in every time it has been used. So, if your pool is always busy, your connection may never idle, and it will never be evicted.

You can also set minIdle to 0 to prevent broken connections from remaining unhandled.