Expiring Vault client tokens in v4.0.0

[wiebeck]

I am currently trying to figure out why my application (running on Kubernetes, using Vault as config source and as provider for dynamic database credentials) runs into situations where the Vault token is expired, so I enabled debug logging for the io.quarkus.vault category.

First of all I noticed that the actual client token gets logged in clear text but this will be fixed in v4.0.1 via #258.

The second thing that made me wonder is that my application actually authenticates twice to Vault. One time to read config properties and another time to request database credentials:

2024-04-09 10:15:11,061 FINE  [io.qua.vau.cli.aut.VaultKubernetesTokenProvider] (main) authenticating with kubernetes jwt: ***
2024-04-09 10:15:11,687 FINE  [io.qua.vau.cli.aut.VaultCachingTokenProvider] (Thread-18) created new login token: {clientToken: ***, renewable: true, leaseDuration: PT2H, valid_until: 2024-04-09T12:15:11.684863016Z}
[...]
2024-04-09 10:15:14,062 FINE  [io.qua.vau.cli.aut.VaultKubernetesTokenProvider] (agroal-11) authenticating with kubernetes jwt: ***
2024-04-09 10:15:14,148 FINE  [io.qua.vau.cli.aut.VaultCachingTokenProvider] (vert.x-eventloop-thread-0) created new login token: {clientToken: ***, renewable: true, leaseDuration: PT2H, valid_until: 2024-04-09T12:15:14.148010177Z}

Note the different threads (main vs. agroal-11) and TTL of 2 hours. As noticed the VaultCachingTokenProvider logs the actual token, so I can see that my application now "knows" about two different Vault tokens.

Is this to be expected? Because I would have expected that the app only uses one single Vault client token no regardless of accessing config source via KV engine or dynamic database credentials.

Now to my main concern: I have configured multiple config sources and I noticed the following in the log when Quarkus needs to refresh the properties from Vault:

2024-04-09 11:31:10,441 FINE  [io.qua.vau.cli.aut.VaultCachingTokenProvider] (executor-thread-45) using cached token ****ZsWmM (expires at 2024-04-09T13:18:32.362355124Z)
2024-04-09 11:31:10,485 FINE  [io.qua.vau.cli.aut.VaultCachingTokenProvider] (executor-thread-45) using cached token ****ZsWmM (expires at 2024-04-09T13:31:10.441921279Z)
2024-04-09 11:31:10,491 FINE  [io.qua.vau.cli.aut.VaultCachingTokenProvider] (executor-thread-45) using cached token ****ZsWmM (expires at 2024-04-09T13:31:10.485707872Z)
2024-04-09 11:31:10,496 FINE  [io.qua.vau.cli.aut.VaultCachingTokenProvider] (executor-thread-45) using cached token ****ZsWmM (expires at 2024-04-09T13:31:10.491859467Z)

Here the same token is being used to refresh the config sources but notice that the expires at timestamp always shows a new time, some milliseconds apart. I really doubt that the token got extended multiple times in a row, so I looked at the source. In io.quarkus.vault.client.auth.VaultCachingTokenProvider#apply after the cached token (in my case non-null) has been determined there comes the following code block that extends the token if necessary (or requests a new one in case we don't have one) and caches the result again:

return CompletableFuture.completedStage(cachedToken)
        // if present, extend token if necessary
        .thenCompose(flatMapPresent(token -> {
            if (token.shouldExtend(renewGracePeriod)) {
                return extend(authRequest, token.getClientToken());
            }
            return CompletableFuture.completedStage(token);
        }))
        // if empty, request new token from delegate
        .thenCompose(flatMapEmptyGet(() -> request(authRequest)))
        // cache token
        .thenApply(vaultToken -> {
            this.cachedToken.set(vaultToken.cached());
            return vaultToken;
        });

Now take a look at this.cachedToken.set(vaultToken.cached());. In case my existing token is still valid and does not need to be extended I expect the cached token not to change at all but when you follow vaultToken.cached() you see that the result is a token that gets a new creation timestamp, which IMHO is simply wrong.

public VaultToken cached() {
    return new VaultToken(clientToken, renewable, leaseDuration, true, instantSource);
}

You're only passing the leaseDuration (2 hours in my case) and the instantSource (I assume that's usually InstantSource.system()), so following the super constructor leads to:

this.created = instantSource.instant();

So the new cached token is a token that has an updated creation timestamp and the same lease duration as the original token. This will make the Vault extension think that the token is always fresh and valid even if it slowly expires as it doesn't actually get extended.

The result is that after 2 hours when at some point my app wants to refresh the config properties I encounter a 403 error when accessing Vault secrets:

ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (executor-thread-77) HTTP Request to [...] failed, error id: [...]: java.lang.RuntimeException: Error injecting java.lang.String org.acme.MyClass.myConfigValue
Caused by: VaultClientException{operationName='VAULT [SECRETS (kv2)] Read Secret', requestPath='https://****/v1/secret/data/*****/platform-config', status=403, errors=[permission denied]}                                                                                                                                      

Before trying to provide a reproducer I first like to know what you think about this. Maybe I am missing something?

Regards

[kdubb]

Is this to be expected? Because I would have expected that the app only uses one single Vault client token no regardless of accessing config source via KV engine or dynamic database credentials.

Yes. The Vault config source now uses a separate client to get around issues with using CDI during application boot/init.

Before trying to provide a reproducer I first like to know what you think about this. Maybe I am missing something?

Your logic seems sound. A reproducer would definitely be helpful.

I'm going to look at the previous version's logic that this code attempted to reproduce and see why vaultToke.cached() is even needed. At first glance, just removing it seems like it would fix it and be the correct behavior.

[kdubb]

@wiebeck Also, thank you for the very detailed analysis. I am in the middle of quite a few other things and this will help get this resolved ASAP.

Another thing you might be able to help with. Can you look at VaultCachingTokenProviderTest and see if your scenario is not covered?

[wiebeck]

Will do once I get the time. Just lost some hours analyzing this issue and need to catch up with my regular work stuff now. Thanks for taking care though! :-)

[kdubb]

@wiebeck Actually, VaultToken.cached() is required to set the cached flag in the VaultToken. You are correct in your deduction that it shouldn't be changing the parent class's VaultTimeLimited.created field.

[kdubb]

I've opened #262 for this issue.

[kdubb]

@wiebeck I've opened #263 with a fix for #262. Are you able to test this PR to see if it fixes your issue?

[wiebeck]

I cannot test your changes in our staging environment but in general they look fine. Some tests for VaultToken would be nice though to make sure that cached() really has no side effects.

[kdubb]

@wiebeck I merged #263. You should be able to build with the latest 4.0.1-SNAPSHOT from the Maven Snapshots repository to test it.

[kdubb]

Sorry, that's incorrect. Quarkiverse doesn't release snapshots automatically.

You can build locally and use the resultant 4.0.1-SNAPSHOT.

[wiebeck]

Awesome! Thanks a lot!

Do you know when regular version 4.0.1 will be released? I think this is a pretty urgent fix affecting a lot of users and I honestly wonder why I'm the first to notice this misbehavior.

[kdubb]

I was hoping to get @vsevel opinion before I did a release. Although it seems important enough to just go ahead with a release.

Were you able to verify it fixes your issue locally? I'd like to get that feedback if possible.

[wiebeck]

@kdubb Yes, I was finally able to verify that the fix indeed works. Now I'm only seeing errors about database credentials getting invalid because the Vault token being used for the database expired - because it hasn't been accessed in 2 hours - which can probably be fixed by recycling DB connections more often, see #72 (comment)

But the token being used for loading propperties is now being refreshed properly.

[kdubb]

@wiebeck I updated #72 to with the current Quarkus property for reactive db clients.