Login token expiring unexpectedly?

[ngc4579]

We are experiencing some kind of strange resp. unexpected behaviour regarding automatic token renewal by LifeCycleAwareSessionManager, perhaps based on misunderstandings of the renewal process.

Setup is as follows: our (containerized) application utilizes spring-vault-core and spring-cloud-vault-config (the latter is used merely to have Spring automatically configure and inject Vault components, and to have an automatic health check). Configuration states spring.cloud.vault.authentication: token and spring.cloud.vault.session.lifecycle.refresh-before-expiry: 15s. The application is scheduled in multiple instances, each of which gets a Vault token on startup, i.e. the same token for all instances. Token TTL / period is defined as 10h. This token expires during application lifetime although I'd expect it does not. In order to track down renewal issues, we have hooked up to the session manager's authentication event listeners. Output from two instances is as follows:

Instance 1:

"@timestamp":"2021-09-12T21:53:36.460+02:00","message":"Token event: org.springframework.vault.authentication.event.BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT8H58M46S]]"
"@timestamp":"2021-09-12T21:53:36.489+02:00","message":"Token event: org.springframework.vault.authentication.event.AfterLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT2H15S]]"
"@timestamp":"2021-09-12T23:53:36.490+02:00","message":"Token event: org.springframework.vault.authentication.event.BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT2H15S]]"
"@timestamp":"2021-09-12T23:53:36.513+02:00","message":"Token event: org.springframework.vault.authentication.event.AfterLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT15S]]"
"@timestamp":"2021-09-12T23:53:37.514+02:00","message":"Token event: org.springframework.vault.authentication.event.BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT15S]]"
"@timestamp":"2021-09-12T23:53:37.527+02:00","message":"Token event: org.springframework.vault.authentication.event.AfterLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT14S]]"
"@timestamp":"2021-09-12T23:53:38.528+02:00","message":"Token event: org.springframework.vault.authentication.event.BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT14S]]"
"@timestamp":"2021-09-12T23:53:38.540+02:00","message":"Token event: org.springframework.vault.authentication.event.AfterLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT13S]]"
"@timestamp":"2021-09-12T23:53:39.541+02:00","message":"Token event: org.springframework.vault.authentication.event.BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT13S]]"
"@timestamp":"2021-09-12T23:53:39.562+02:00","message":"Token event: org.springframework.vault.authentication.event.AfterLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT12S]]"
"@timestamp":"2021-09-12T23:53:40.563+02:00","message":"Token event: org.springframework.vault.authentication.event.BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT12S]]"
"@timestamp":"2021-09-12T23:53:40.585+02:00","message":"Token event: org.springframework.vault.authentication.event.AfterLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT11S]]"
"@timestamp":"2021-09-12T23:53:41.586+02:00","message":"Token event: org.springframework.vault.authentication.event.BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT11S]]"
"@timestamp":"2021-09-12T23:53:41.597+02:00","message":"Token event: org.springframework.vault.authentication.event.AfterLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT10S]]"
"@timestamp":"2021-09-12T23:53:42.597+02:00","message":"Token event: org.springframework.vault.authentication.event.BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT10S]]"
"@timestamp":"2021-09-12T23:53:42.611+02:00","message":"Token event: org.springframework.vault.authentication.event.AfterLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT9S]]"
"@timestamp":"2021-09-12T23:53:43.611+02:00","message":"Token event: org.springframework.vault.authentication.event.BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT9S]]"
"@timestamp":"2021-09-12T23:53:43.638+02:00","message":"Token event: org.springframework.vault.authentication.event.AfterLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT8S]]"
"@timestamp":"2021-09-12T23:53:44.640+02:00","message":"Token event: org.springframework.vault.authentication.event.BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT8S]]"
"@timestamp":"2021-09-12T23:53:44.679+02:00","message":"Token event: org.springframework.vault.authentication.event.LoginTokenExpiredEvent[source=LoginToken [renewable=true, leaseDuration=PT7S]]"

Instance 2:
"@timestamp":"2021-09-12T21:53:36.137+02:00","message":"Token event: org.springframework.vault.authentication.event.BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT8H58M36S]]"
"@timestamp":"2021-09-12T21:53:36.164+02:00","message":"Token event: org.springframework.vault.authentication.event.AfterLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT2H15S]]"
"@timestamp":"2021-09-12T23:53:36.166+02:00","message":"Token event: org.springframework.vault.authentication.event.BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT2H15S]]"
"@timestamp":"2021-09-12T23:53:36.179+02:00","message":"Token event: org.springframework.vault.authentication.event.AfterLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT15S]]"
"@timestamp":"2021-09-12T23:53:37.179+02:00","message":"Token event: org.springframework.vault.authentication.event.BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT15S]]"
"@timestamp":"2021-09-12T23:53:37.193+02:00","message":"Token event: org.springframework.vault.authentication.event.AfterLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT14S]]"
"@timestamp":"2021-09-12T23:53:38.194+02:00","message":"Token event: org.springframework.vault.authentication.event.BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT14S]]"
"@timestamp":"2021-09-12T23:53:38.206+02:00","message":"Token event: org.springframework.vault.authentication.event.AfterLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT13S]]"
"@timestamp":"2021-09-12T23:53:39.206+02:00","message":"Token event: org.springframework.vault.authentication.event.BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT13S]]"
"@timestamp":"2021-09-12T23:53:39.219+02:00","message":"Token event: org.springframework.vault.authentication.event.AfterLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT12S]]"
"@timestamp":"2021-09-12T23:53:40.220+02:00","message":"Token event: org.springframework.vault.authentication.event.BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT12S]]"
"@timestamp":"2021-09-12T23:53:40.234+02:00","message":"Token event: org.springframework.vault.authentication.event.AfterLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT11S]]"
"@timestamp":"2021-09-12T23:53:41.234+02:00","message":"Token event: org.springframework.vault.authentication.event.BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT11S]]"
"@timestamp":"2021-09-12T23:53:41.254+02:00","message":"Token event: org.springframework.vault.authentication.event.AfterLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT10S]]"
"@timestamp":"2021-09-12T23:53:42.254+02:00","message":"Token event: org.springframework.vault.authentication.event.BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT10S]]"
"@timestamp":"2021-09-12T23:53:42.277+02:00","message":"Token event: org.springframework.vault.authentication.event.AfterLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT9S]]"
"@timestamp":"2021-09-12T23:53:43.278+02:00","message":"Token event: org.springframework.vault.authentication.event.BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT9S]]"
"@timestamp":"2021-09-12T23:53:43.291+02:00","message":"Token event: org.springframework.vault.authentication.event.AfterLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT8S]]"
"@timestamp":"2021-09-12T23:53:44.291+02:00","message":"Token event: org.springframework.vault.authentication.event.BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT8S]]"
"@timestamp":"2021-09-12T23:53:44.314+02:00","message":"Token event: org.springframework.vault.authentication.event.LoginTokenExpiredEvent[source=LoginToken [renewable=true, leaseDuration=PT7S]]"

As to above stated configuration (refresh-before-expiry) I'd expect the token would be renewed indefinitely during application lifetime. What actually happens though remains a mystery to me - above log entries seem to show really strange behaviour.

From T23:53:36.166 on the session manager seems to periodically (every second) try to renew the token until it eventually expires at T23:53:44.314 (Instance 2), similarly from T23:53:36.490 until T23:53:44.679 on Instance 1. The listener does not catch any additional authentication errors or other events during this process.

Can someone please explain this behaviour?

[ngc4579]

Addition: What might cause the renewal process to obtain a LoginToken whose lease duration is exactly the same both before and after renewal? Is it even possible that a renew-self request does actually fail (i.e. not renewing the token) without issuing a message? At least this is suggested by looking at the relevant portion of LifeCycleAwareSessionManager:

        VaultResponse vaultResponse = (VaultResponse)this.restOperations.postForObject("auth/token/renew-self", new HttpEntity(VaultHttpHeaders.from(wrapper.token)), VaultResponse.class, new Object[0]);
        LoginToken renewed = LoginTokenUtil.from(vaultResponse.getRequiredAuth());

(LifeCycleAwareSessionManager#doRenew)

Or might this somehow be related to two (or more) instances simultaneously trying to renew the same token?

[mp911de]

I'm not quite sure what you're asking for. Renewal is to keep a token alive. It signals towards Vault, that the application is still alive so that the token doesn't expire in the middle of an operation. Renewal happens until reaching max_ttl, afterwards, the token is considered expired and won't be used anymore.

The session manager implementation cares about resource usage. If the token is expired and there's no interaction with Vault, then no subsequent token is acquired unless there's further Vault activity. The first request to Vault will acquire a new session token by using the login method.

That way we avoid wasting resources if e.g. the application obtains secrets only once upon startup.

[ngc4579]

The token in request is a periodic service token issued with vault token create -policy=<some policy> -period <duration> and as such should never expire when renewed properly. So in fact the issue is not about re-login after token expiry, but actually about some kind of failure in the process of token renewal.

Our application receives the token via spring.cloud.vault.token=<token> and performs an initial secret retrieval upon startup, so the session manager should be in place caring for token renewal. As seen in above stated logs, token renewal is attempted but seems to be to no avail, as the lease duration after renewal is not reset. max_ttl should never be reached.

Key                  Value
---                  -----
accessor             <redacted>
creation_time        1631531847
creation_ttl         2h
display_name         token
entity_id            n/a
expire_time          2021-09-13T21:16:42.566292538+02:00
explicit_max_ttl     0s
id                   <redacted>
issue_time           2021-09-13T13:17:27.979229121+02:00
last_renewal         2021-09-13T19:16:42.566292702+02:00
last_renewal_time    1631553402
meta                 <nil>
num_uses             0
orphan               false
path                 auth/token/create
period               2h
policies             [default rss]
renewable            true
ttl                  1h51m10s
type                 service

[mp911de]

According to the log, the very first token had a TTL of PT8H58M36S (~ 9hrs). It has been renewed when the token had 2hrs 15sec left (note the 15sec that stem from spring.cloud.vault.session.lifecycle.refresh-before-expiry). Upon renewal, Spring Vault reuses the response of /auth/token/renew-self to determine the remaining TTL and it's the Vault server that supplies the remaining TTL.

Renewal extends the TTL in predefined increments until hitting max_ttl. If the returned TTL from the renewal is less than spring.cloud.vault.session.lifecycle.refresh-before-expiry + 2seconds, then Spring Vault considers the token expired.

In the last remaining seconds of the remaining TTL, Spring Vault increases the rate at which the token is renewed to cater for GC pauses to some extent as exact timing can be tricky with non-realtime systems.

[ngc4579]

So it rather seems that Vault does in fact not renew the token in request as its TTL is not reset, as seen in the logs above...?

...
BeforeLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT10S]]
AfterLoginTokenRenewedEvent[source=LoginToken [renewable=true, leaseDuration=PT9S]]
...

[mp911de]

It indeed is renewed. As per

Upon renewal, Spring Vault reuses the response of /auth/token/renew-self to determine the remaining TTL

The remaining 10...9...8... seconds are a response from Vault. Since the token TTL is already at max_ttl, any subsequent calls to renew will not extend the TTL but return the remaining TTL.

[ngc4579]

Thank you for clarification - as the response actually reflects the remaining TTL, this rather seems to be a Vault issue, if at all - according to their documentation these periodic service tokens should never expire if properly renewed (and without an explicit max TTL). I'll head over to stackoverflow. Thanks for your patience. :)