search

quarkiverse / quarkus-vault

Quarkus HashiCorp Vault extension
Apache License 2.0
19 stars 26 forks source link

Quarkus vault with Dynamic Database Credentials fails to refresh jdbc connection #66

Closed jkalex-git closed 2 years ago

jkalex-git commented 2 years ago

Describe the bug Quarkus vault with Dynamic Database Credentials fails to refresh jdbc connection. The quarkus jdbc connection still uses the existing connection even after the ephemeral credentials are expired (TTL expired) and the user is removed from DB by vault. This is making the Dynamic Database Credentials feature unusable.

Expected behavior The vault plugin refresh the connection or put an expiry to the active connection using the TTL value. Any new request to DB should create a new connection with the new credentials.

Actual behavior Access denied to tables during request. To make it worse health check still returns a success.

How to Reproduce? Reproduced the issue using the below quickstart, https://github.com/jkalex-git/vault-dynamic-postgres

Steps to start application,

Java Version - 17 Quarkus Version - 2.11.2.Final

Additional information This might be related to https://github.com/quarkiverse/quarkus-vault/issues/65

vsevel commented 2 years ago

this is where the magic should happen: https://github.com/quarkiverse/quarkus-vault/blob/1.1.0/runtime/src/main/java/io/quarkus/vault/runtime/VaultDynamicCredentialsManager.java#L73-L95

can you activate the debug logs on that class?

also it relies on the agroal pool not caching the credentials. at some point we should see something like lease X has become invalid then extended X credentials:

kdubb commented 2 years ago

I would say that currently this is a documentation issue. Currently it requires requests from the credentials consumer (e.g. the driver or pool) to renew leases.

jkalex-git commented 2 years ago

The issue is the connection is still active in the pool and is not trying to get a new connection.

2022-08-19 18:39:56,977 DEBUG [org.jbo.res.res.i18n] (executor-thread-0) RESTEASY002315: PathInfo: /hello
2022-08-19 18:39:56,977 DEBUG [org.hib.res.jdb.int.LogicalConnectionManagedImpl] (executor-thread-0) hibernate.connection.provider_disables_autocommit was enabled.  This setting should only be enabled when you are certain that the Connections given to Hibernate by the ConnectionProvider have auto-commit disabled.  Enabling this setting when the Connections do not have auto-commit disabled will lead to Hibernate executing SQL operations outside of any JDBC/SQL transaction.
2022-08-19 18:39:56,977 DEBUG [org.hib.res.tra.bac.jta.int.JtaTransactionCoordinatorImpl] (executor-thread-0) Hibernate RegisteredSynchronization successfully registered with JTA platform
2022-08-19 18:39:56,977 DEBUG [org.hib.SQL] (executor-thread-0) select item0_.id as id1_0_, item0_.name as name2_0_ from items item0_
2022-08-19 18:39:56,978 FINE  [org.pos.jdb.PgConnection] (executor-thread-0)   setAutoCommit = false
2022-08-19 18:39:56,981 DEBUG [org.hib.eng.jdb.spi.SqlExceptionHelper] (executor-thread-0) could not extract ResultSet [n/a]: org.postgresql.util.PSQLException: ERROR: permission denied for table items
    at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2676)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2366)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:356)
    at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:490)
    at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:408)
    at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:181)
    at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:133)
    at io.agroal.pool.wrapper.PreparedStatementWrapper.executeQuery(PreparedStatementWrapper.java:78)
    at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:57)
    at org.hibernate.loader.Loader.getResultSet(Loader.java:2322)
    at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2075)
    at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2037)
    at org.hibernate.loader.Loader.doQuery(Loader.java:956)
    at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:357)
    at org.hibernate.loader.Loader.doList(Loader.java:2868)
    at org.hibernate.loader.Loader.doList(Loader.java:2850)
    at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2682)
    at org.hibernate.loader.Loader.list(Loader.java:2677)
    at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:540)
    at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:400)
    at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:219)
    at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1459)
    at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1649)
    at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1617)
    at org.hibernate.query.Query.getResultList(Query.java:165)
    at org.acme.quickstart.GreetingResource.getItems(GreetingResource.java:26)
    at org.acme.quickstart.GreetingResource_Subclass.getItems$$superforward1(Unknown Source)
    at org.acme.quickstart.GreetingResource_Subclass$$function$$1.apply(Unknown Source)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:53)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.proceed(InvocationInterceptor.java:62)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.monitor(InvocationInterceptor.java:49)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor_Bean.intercept(Unknown Source)
    at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:49)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:133)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:104)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:38)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:58)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:32)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired_Bean.intercept(Unknown Source)
    at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:40)
    at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
    at org.acme.quickstart.GreetingResource_Subclass.getItems(Unknown Source)
    at org.acme.quickstart.GreetingResource.hello(GreetingResource.java:21)
    at org.acme.quickstart.GreetingResource_Subclass.hello$$superforward1(Unknown Source)
    at org.acme.quickstart.GreetingResource_Subclass$$function$$2.apply(Unknown Source)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:53)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.proceed(InvocationInterceptor.java:62)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.monitor(InvocationInterceptor.java:49)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor_Bean.intercept(Unknown Source)
    at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:40)
    at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
    at org.acme.quickstart.GreetingResource_Subclass.hello(Unknown Source)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:170)
    at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:130)
    at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:660)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:524)
    at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:474)
    at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:476)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:434)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:408)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:69)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:492)
    at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:261)
    at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:161)
    at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
    at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:164)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:247)
    at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:151)
    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:91)
    at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:555)
    at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
    at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
    at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:833)

2022-08-19 18:39:56,981 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (executor-thread-0) SQL Error: 0, SQLState: 42501
2022-08-19 18:39:56,982 ERROR [org.hib.eng.jdb.spi.SqlExceptionHelper] (executor-thread-0) ERROR: permission denied for table items
2022-08-19 18:39:56,984 DEBUG [org.hib.eng.tra.int.TransactionImpl] (executor-thread-0) On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
2022-08-19 18:39:56,986 FINE  [org.pos.jdb.PgConnection] (executor-thread-0)   setAutoCommit = true
2022-08-19 18:39:56,986 DEBUG [org.hib.res.jdb.int.LogicalConnectionManagedImpl] (executor-thread-0) Initiating JDBC connection release from afterTransaction
jkalex-git commented 2 years ago

I added quarkus.datasource.jdbc.max-lifetime=1M in application properties. This will force to get a new connection and issue is not there.

2022-08-19 18:46:09,967 DEBUG [org.jbo.res.res.i18n] (executor-thread-0) RESTEASY002315: PathInfo: /hello
2022-08-19 18:46:09,970 DEBUG [org.hib.res.jdb.int.LogicalConnectionManagedImpl] (executor-thread-0) `hibernate.connection.provider_disables_autocommit` was enabled.  This setting should only be enabled when you are certain that the Connections given to Hibernate by the ConnectionProvider have auto-commit disabled.  Enabling this setting when the Connections do not have auto-commit disabled will lead to Hibernate executing SQL operations outside of any JDBC/SQL transaction.
2022-08-19 18:46:09,970 DEBUG [org.hib.res.tra.bac.jta.int.JtaTransactionCoordinatorImpl] (executor-thread-0) Hibernate RegisteredSynchronization successfully registered with JTA platform
2022-08-19 18:46:09,970 DEBUG [org.hib.SQL] (executor-thread-0) select item0_.id as id1_0_, item0_.name as name2_0_ from items item0_
2022-08-19 18:46:09,988 DEBUG [io.qua.vau.run.VaultDynamicCredentialsManager] (agroal-11) lease database/creds/postgres-gift/kY7DyHkCKGnJGO7FN1tF0WBK has become invalid
2022-08-19 18:46:10,000 DEBUG [io.qua.vau.run.VaultDynamicCredentialsManager] (agroal-11) generated postgres-gift(database/creds) credentials:{leaseId: database/creds/postgres-gift/eqpGZfMQ6uMVUkXS46T8cecj, renewable: true, leaseDuration: 120s, valid_until: Fri Aug 19 18:48:10 CEST 2022, username: v-token-postgres-qofbQFylBnBeH6ZwUMOj-1660927569, password:***}
2022-08-19 18:46:10,000 WARN  [io.qua.vau.run.TimeLimitedBase] (agroal-11) postgres-gift (database/creds) lease duration 120s is smaller than the renew grace period 3600s
2022-08-19 18:46:10,001 FINE  [org.pos.Driver] (agroal-11) Connecting with URL: jdbc:postgresql://localhost:5432/gift
2022-08-19 18:46:10,001 FINE  [org.pos.jdb.PgConnection] (agroal-11) PostgreSQL JDBC Driver 42.4.0
2022-08-19 18:46:10,001 FINE  [org.pos.jdb.PgConnection] (agroal-11)   setDefaultFetchSize = 0
2022-08-19 18:46:10,001 FINE  [org.pos.jdb.PgConnection] (agroal-11)   setPrepareThreshold = 5
2022-08-19 18:46:10,001 FINE  [org.pos.cor.v3.ConnectionFactoryImpl] (agroal-11) Trying to establish a protocol version 3 connection to localhost:5432
2022-08-19 18:46:10,001 FINE  [org.pos.cor.v3.ConnectionFactoryImpl] (agroal-11) Receive Buffer Size is 65,536
2022-08-19 18:46:10,001 FINE  [org.pos.cor.v3.ConnectionFactoryImpl] (agroal-11) Send Buffer Size is 1,313,280
2022-08-19 18:46:10,007 FINE  [org.pos.jdb.PgConnection] (executor-thread-0)   setAutoCommit = false
2022-08-19 18:46:10,008 DEBUG [org.hib.loa.Loader] (executor-thread-0) Result set row: 0
2022-08-19 18:46:10,008 DEBUG [org.hib.loa.Loader] (executor-thread-0) Result row: EntityKey[org.acme.quickstart.Item#1]
2022-08-19 18:46:10,008 DEBUG [org.hib.loa.Loader] (executor-thread-0) Result set row: 1
2022-08-19 18:46:10,008 DEBUG [org.hib.loa.Loader] (executor-thread-0) Result row: EntityKey[org.acme.quickstart.Item#2]
2022-08-19 18:46:10,008 DEBUG [org.hib.eng.int.TwoPhaseLoad] (executor-thread-0) Resolving attributes for [org.acme.quickstart.Item#1]
2022-08-19 18:46:10,008 DEBUG [org.hib.eng.int.TwoPhaseLoad] (executor-thread-0) Processing attribute `name` : value = TeddyBear
2022-08-19 18:46:10,008 DEBUG [org.hib.eng.int.TwoPhaseLoad] (executor-thread-0) Attribute (`name`)  - enhanced for lazy-loading? - false
2022-08-19 18:46:10,008 DEBUG [org.hib.eng.int.TwoPhaseLoad] (executor-thread-0) Done materializing entity [org.acme.quickstart.Item#1]
2022-08-19 18:46:10,009 DEBUG [org.hib.eng.int.TwoPhaseLoad] (executor-thread-0) Resolving attributes for [org.acme.quickstart.Item#2]
2022-08-19 18:46:10,009 DEBUG [org.hib.eng.int.TwoPhaseLoad] (executor-thread-0) Processing attribute `name` : value = Playstation
2022-08-19 18:46:10,009 DEBUG [org.hib.eng.int.TwoPhaseLoad] (executor-thread-0) Attribute (`name`)  - enhanced for lazy-loading? - false
2022-08-19 18:46:10,009 DEBUG [org.hib.eng.int.TwoPhaseLoad] (executor-thread-0) Done materializing entity [org.acme.quickstart.Item#2]
2022-08-19 18:46:10,009 DEBUG [org.hib.eve.int.AbstractFlushingEventListener] (executor-thread-0) Processing flush-time cascades
2022-08-19 18:46:10,009 DEBUG [org.hib.eve.int.AbstractFlushingEventListener] (executor-thread-0) Dirty checking collections
2022-08-19 18:46:10,009 DEBUG [org.hib.eve.int.AbstractFlushingEventListener] (executor-thread-0) Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects
2022-08-19 18:46:10,009 DEBUG [org.hib.eve.int.AbstractFlushingEventListener] (executor-thread-0) Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2022-08-19 18:46:10,009 DEBUG [org.hib.int.uti.EntityPrinter] (executor-thread-0) Listing entities:
2022-08-19 18:46:10,009 DEBUG [org.hib.int.uti.EntityPrinter] (executor-thread-0) org.acme.quickstart.Item{name=TeddyBear, id=1}
2022-08-19 18:46:10,009 DEBUG [org.hib.int.uti.EntityPrinter] (executor-thread-0) org.acme.quickstart.Item{name=Playstation, id=2}
2022-08-19 18:46:10,009 DEBUG [org.hib.eng.tra.int.TransactionImpl] (executor-thread-0) On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
2022-08-19 18:46:10,009 DEBUG [org.hib.res.jdb.int.LogicalConnectionManagedImpl] (executor-thread-0) Initiating JDBC connection release from beforeTransactionCompletion
2022-08-19 18:46:10,010 FINE  [org.pos.jdb.PgConnection] (executor-thread-0)   setAutoCommit = true
2022-08-19 18:46:10,010 DEBUG [org.hib.res.jdb.int.LogicalConnectionManagedImpl] (executor-thread-0) Initiating JDBC connection release from afterTransaction
2022-08-19 18:46:10,010 DEBUG [org.jbo.res.res.i18n] (executor-thread-0) MessageBodyWriter: org.jboss.resteasy.core.providerfactory.SortedKey
2022-08-19 18:46:10,010 DEBUG [org.jbo.res.res.i18n] (executor-thread-0) MessageBodyWriter: org.jboss.resteasy.plugins.providers.DefaultTextPlain
2022-08-19 18:46:10,010 DEBUG [org.jbo.res.res.i18n] (executor-thread-0) MessageBodyWriter: org.jboss.resteasy.plugins.providers.DefaultTextPlain
2022-08-19 18:46:10,010 DEBUG [org.jbo.res.res.i18n] (executor-thread-0) MessageBodyWriter: org.jboss.resteasy.core.providerfactory.SortedKey
2022-08-19 18:46:10,010 DEBUG [org.jbo.res.res.i18n] (executor-thread-0) Interceptor Context: org.jboss.resteasy.core.interception.jaxrs.ServerWriterInterceptorContext,  Method : proceed
2022-08-19 18:46:10,011 DEBUG [org.jbo.res.res.i18n] (executor-thread-0) MessageBodyWriter: org.jboss.resteasy.core.providerfactory.SortedKey
2022-08-19 18:46:10,011 DEBUG [org.jbo.res.res.i18n] (executor-thread-0) MessageBodyWriter: org.jboss.resteasy.plugins.providers.DefaultTextPlain
kdubb commented 2 years ago

Yes that's how it works at the moment. It is required that the pool expire connections at a regular interval to ensure it requests new credentials from quarkus-vault which will then renew or create credentials as needed.

kdubb commented 2 years ago

That's why I said this is essentially a documentation issue currently. It works as designed and the documentation needs to educate users of this design.

jkalex-git commented 2 years ago

I don't think its just a documentation issue. This should be handled by expiring the connection based on the ttl value. The issue is connection is still active. Maybe this is not the issue of the vault plugin but an issue of the quarkus-jdbc-postgresql.

The workaround with max-lifetime is not a solution. This reduced the number of occurrences of the issue. But it happens, causing random crashes in our application. The working should be similar to Auth OIDC flow, where the refresh token is requested if the token expiry is near or expired.

kdubb commented 2 years ago

Expiring connections using lifetime works reliably. We use it and have not seen any issues with expirations in development or production. As an example, our connections lifetime is 1 hour and credentials expire after 6 hours.

As I said, this is how it is designed currently and it works as expected. If you wish to discuss different behavior please do so in #65.

kdubb commented 2 years ago

FYI, the default TTL for Vault dynamic credentials is 1 hour. So lifetimes of 10, 15, or even 20 minutes should work without issue.

vsevel commented 2 years ago

It is indeed the responsibility of the client (e.g. the agroal pool) to not cache credentials, and the application developer to setup recycling connections with a delay smaller than the vault credentials TTL. In this implementation, it is working as designed. If you want to limit the number of reconnections, just extend the renewal periods.

jkalex-git commented 2 years ago

default_ttl is set at 12 Hours max_ttl is set at 16 days And connection lifetime is set at 30 minutes for our production system. The issue happened couple of times; one of them happened after 63 days from last restart.

I agree with you that it is working as designed. But it does not solve the issue. Maybe playing around with above numbers would make the issue less occurring, but I would respectfully argue that its not an ideal solution.

kdubb commented 2 years ago

If that is the case then I would guess that you are not actually encountering the issue we are discussing or there is an unknown issue with the renewal behavior.

Unfortunately the reproducer you provided reproduces designed behavior so it's not helpful to debug your specific issue.

@vsevel Suggested activating logs on the VaultDynamicCredentialsManager. I would suggest doing that and providing us with relevant logs from an actual failure.

jkalex-git commented 2 years ago

I will do that and open a new ticket when it occurs. Thank you for your support.