Vault Agent lease cache interferes with template refresh for dynamic secrets

greghensley commented 1 year ago

Describe the bug

The Vault Agent template server can fail to refresh secrets before lease expiration when the Vault Agent is configured with

A template stanza using a dynamic (leased) secret
A cache stanza (lease-cache enabled)
use_auto_auth_token set to either true or "force"

All requests issued by the Template server are sent via the Agent's API Proxy using the current Auto-Auth token. When use_auto_auth_token is enabled, the current Auto-Auth token is registered in the Lease Cache. As a result, the Lease Cache will intercept all requests made by the Template server and internally handle renewal of any leases returned to the Template server.[^1]

The Lease Cache will also intercept requests from the Template server to v1/sys/leases/renew and will cache these responses because the response message is interpreted as a secret due to its "lease_id" field.[^2] As a result, until the Lease Cache's internal renewal loop finishes, all future renewal attempts from the Template server will be served from the cache -- even as the lease is approaching it's max_ttl, the Template server will be receive responses which suggest the lease is still being renewed for the entire default ttl (rather than the true truncated duration up to the max_ttl). This results in the Template server waiting up to ttl*2/3 seconds (the normal lease renewal period) after the lease has expired before requesting a new secret and re-rendering the template.

To Reproduce

Example Agent config.hcl. Modify for your Vault token file location and dynamic secret API path.

``` template { contents = <

Configure a dynamic secret on a Vault Server with a short TTL and Maximum TTL (recommend 5m TTL and 10m MaxTTL).
Login with sufficient rights to fetch the secret and renew leases.
Run the Vault Agent: vault agent -log-level debug -config config.hcl

Example Agent log

``` ==> Vault Agent configuration: Api Address 1: unix://./vault.sock Api Address 2: http://bufconn Cgo: disabled Log Level: debug Version: Vault v1.13.0, built 2023-03-01T14:58:13Z Version Sha: a4cf0dc4437de35fce4860857b64569d092a9b5a+CHANGES 2023-03-22T13:41:53.469-0700 [DEBUG] agent.apiproxy: auto-auth token is allowed to be used; configuring inmem sink 2023-03-22T13:41:53.469-0700 [DEBUG] agent.apiproxy: auto-auth token is allowed to be used; configuring inmem sink 2023-03-22T13:41:53.469-0700 [DEBUG] agent: would have sent systemd notification (systemd not present): notification=READY=1 2023-03-22T13:41:53.469-0700 [INFO] agent.template.server: starting template server 2023-03-22T13:41:53.469-0700 [INFO] agent.auth.handler: starting auth handler 2023-03-22T13:41:53.469-0700 [INFO] agent.auth.handler: authenticating 2023-03-22T13:41:53.469-0700 [INFO] agent.sink.server: starting sink server 2023-03-22T13:41:53.469-0700 [INFO] (runner) creating new runner (dry: false, once: false) 2023-03-22T13:41:53.469-0700 [DEBUG] (runner) final config: {"Consul":{"Address":"","Namespace":"","Auth":{"Enabled":false,"Username":""},"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true},"SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":false,"Key":"","ServerName":"","Verify":true},"Token":"","TokenFile":"","Transport":{"CustomDialer":null,"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":13,"TLSHandshakeTimeout":10000000000}},"Dedup":{"Enabled":false,"MaxStale":2000000000,"Prefix":"consul-template/dedup/","TTL":15000000000,"BlockQueryWaitTime":60000000000},"DefaultDelims":{"Left":null,"Right":null},"Exec":{"Command":[],"Enabled":false,"Env":{"Denylist":[],"Custom":[],"Pristine":false,"Allowlist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":0},"KillSignal":2,"LogLevel":"DEBUG","FileLog":{"LogFilePath":"","LogRotateBytes":0,"LogRotateDuration":86400000000000,"LogRotateMaxFiles":0},"MaxStale":2000000000,"PidFile":"","ReloadSignal":1,"Syslog":{"Enabled":false,"Facility":"LOCAL0","Name":"consul-template"},"Templates":[{"Backup":false,"Command":[],"CommandTimeout":30000000000,"Contents":"{{- with secret \"path/to/dynamic/secret\" }}\n{{- .Data | toJSONPretty }}\n{{- end }}\n","CreateDestDirs":true,"Destination":"./secret.txt","ErrMissingKey":false,"ErrFatal":true,"Exec":{"Command":[],"Enabled":false,"Env":{"Denylist":[],"Custom":[],"Pristine":false,"Allowlist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":30000000000},"Perms":0,"User":null,"Uid":null,"Group":null,"Gid":null,"Source":"","Wait":{"Enabled":false,"Min":0,"Max":0},"LeftDelim":"","RightDelim":"","FunctionDenylist":[],"SandboxPath":""}],"TemplateErrFatal":null,"Vault":{"Address":"http://127.0.0.1:8200","Enabled":true,"Namespace":"","RenewToken":false,"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true},"SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":false,"Key":"","ServerName":"","Verify":false},"Transport":{"CustomDialer":{},"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":13,"TLSHandshakeTimeout":10000000000},"UnwrapToken":false,"DefaultLeaseDuration":300000000000,"LeaseRenewalThreshold":0.9,"K8SAuthRoleName":"","K8SServiceAccountTokenPath":"/run/secrets/kubernetes.io/serviceaccount/token","K8SServiceAccountToken":"","K8SServiceMountPath":"kubernetes"},"Nomad":{"Address":"","Enabled":false,"Namespace":"","SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":false,"Key":"","ServerName":"","Verify":true},"AuthUsername":"","AuthPassword":"","Transport":{"CustomDialer":null,"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":13,"TLSHandshakeTimeout":10000000000},"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true}},"Wait":{"Enabled":false,"Min":0,"Max":0},"Once":false,"ParseOnly":false,"BlockQueryWaitTime":60000000000} 2023-03-22T13:41:53.469-0700 [INFO] (runner) creating watcher 2023-03-22T13:41:53.498-0700 [INFO] agent.auth.handler: authentication successful, sending token to sinks 2023-03-22T13:41:53.499-0700 [INFO] agent.auth.handler: starting renewal process 2023-03-22T13:41:53.499-0700 [INFO] agent.template.server: template server received new token 2023-03-22T13:41:53.499-0700 [INFO] (runner) stopping 2023-03-22T13:41:53.499-0700 [DEBUG] (runner) stopping watcher 2023-03-22T13:41:53.499-0700 [DEBUG] (watcher) stopping all views 2023-03-22T13:41:53.499-0700 [INFO] (runner) creating new runner (dry: false, once: false) 2023-03-22T13:41:53.499-0700 [DEBUG] agent.cache.leasecache: storing auto-auth token into the cache 2023-03-22T13:41:53.499-0700 [DEBUG] (runner) final config: {"Consul":{"Address":"","Namespace":"","Auth":{"Enabled":false,"Username":""},"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true},"SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":false,"Key":"","ServerName":"","Verify":true},"Token":"","TokenFile":"","Transport":{"CustomDialer":null,"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":13,"TLSHandshakeTimeout":10000000000}},"Dedup":{"Enabled":false,"MaxStale":2000000000,"Prefix":"consul-template/dedup/","TTL":15000000000,"BlockQueryWaitTime":60000000000},"DefaultDelims":{"Left":null,"Right":null},"Exec":{"Command":[],"Enabled":false,"Env":{"Denylist":[],"Custom":[],"Pristine":false,"Allowlist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":0},"KillSignal":2,"LogLevel":"DEBUG","FileLog":{"LogFilePath":"","LogRotateBytes":0,"LogRotateDuration":86400000000000,"LogRotateMaxFiles":0},"MaxStale":2000000000,"PidFile":"","ReloadSignal":1,"Syslog":{"Enabled":false,"Facility":"LOCAL0","Name":"consul-template"},"Templates":[{"Backup":false,"Command":[],"CommandTimeout":30000000000,"Contents":"{{- with secret \"path/to/dynamic/secret\" }}\n{{- scratch.MapSet \"secret\" \"request_id\" .RequestID }}\n{{- scratch.MapSet \"secret\" \"lease_id\" .LeaseID }}\n{{- scratch.MapSet \"secret\" \"lease_duration\" .LeaseDuration }}\n{{- scratch.MapSet \"secret\" \"renewable\" .Renewable }} \n{{- scratch.Get \"secret\" | toJSONPretty }}\n{{- end }}\n","CreateDestDirs":true,"Destination":"./secret.txt","ErrMissingKey":false,"ErrFatal":true,"Exec":{"Command":[],"Enabled":false,"Env":{"Denylist":[],"Custom":[],"Pristine":false,"Allowlist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":30000000000},"Perms":0,"User":null,"Uid":null,"Group":null,"Gid":null,"Source":"","Wait":{"Enabled":false,"Min":0,"Max":0},"LeftDelim":"","RightDelim":"","FunctionDenylist":[],"SandboxPath":""}],"TemplateErrFatal":null,"Vault":{"Address":"http://127.0.0.1:8200","Enabled":true,"Namespace":"","RenewToken":false,"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true},"SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":false,"Key":"","ServerName":"","Verify":false},"Transport":{"CustomDialer":{},"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":13,"TLSHandshakeTimeout":10000000000},"UnwrapToken":false,"DefaultLeaseDuration":300000000000,"LeaseRenewalThreshold":0.9,"K8SAuthRoleName":"","K8SServiceAccountTokenPath":"/run/secrets/kubernetes.io/serviceaccount/token","K8SServiceAccountToken":"","K8SServiceMountPath":"kubernetes"},"Nomad":{"Address":"","Enabled":false,"Namespace":"","SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":false,"Key":"","ServerName":"","Verify":true},"AuthUsername":"","AuthPassword":"","Transport":{"CustomDialer":null,"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":13,"TLSHandshakeTimeout":10000000000},"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true}},"Wait":{"Enabled":false,"Min":0,"Max":0},"Once":false,"ParseOnly":false,"BlockQueryWaitTime":60000000000} 2023-03-22T13:41:53.499-0700 [INFO] (runner) creating watcher 2023-03-22T13:41:53.499-0700 [INFO] (runner) starting 2023-03-22T13:41:53.499-0700 [DEBUG] (runner) running initial templates 2023-03-22T13:41:53.499-0700 [DEBUG] (runner) initiating run 2023-03-22T13:41:53.499-0700 [DEBUG] (runner) checking template 842ad7d3a2a51f618cfe1ee5c2bed1aa 2023-03-22T13:41:53.499-0700 [DEBUG] (runner) missing data for 1 dependencies 2023-03-22T13:41:53.499-0700 [DEBUG] (runner) missing dependency: vault.read(path/to/dynamic/secret) 2023-03-22T13:41:53.499-0700 [DEBUG] (runner) add used dependency vault.read(path/to/dynamic/secret) to missing since isLeader but do not have a watcher 2023-03-22T13:41:53.499-0700 [DEBUG] (runner) was not watching 1 dependencies 2023-03-22T13:41:53.499-0700 [DEBUG] (watcher) adding vault.read(path/to/dynamic/secret) 2023-03-22T13:41:53.499-0700 [DEBUG] (runner) diffing and updating dependencies 2023-03-22T13:41:53.499-0700 [DEBUG] (runner) watching 1 dependencies 2023-03-22T13:41:53.499-0700 [INFO] agent.apiproxy: received request: method=GET path=/v1/sys/internal/ui/mounts/path/to/dynamic/secret 2023-03-22T13:41:53.500-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=GET path=/v1/sys/internal/ui/mounts/path/to/dynamic/secret 2023-03-22T13:41:53.500-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=GET path=/v1/sys/internal/ui/mounts/path/to/dynamic/secret 2023-03-22T13:41:53.500-0700 [DEBUG] agent.apiproxy.client: performing request: method=GET url=https://vault.local/v1/sys/internal/ui/mounts/path/to/dynamic/secret 2023-03-22T13:41:53.528-0700 [DEBUG] agent.cache.leasecache: pass-through response; secret not renewable: method=GET path=/v1/sys/internal/ui/mounts/path/to/dynamic/secret 2023-03-22T13:41:53.528-0700 [INFO] agent.apiproxy: received request: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:41:53.528-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:41:53.528-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:41:53.528-0700 [DEBUG] agent.apiproxy.client: performing request: method=GET url=https://vault.local/v1/path/to/dynamic/secret 2023-03-22T13:41:53.536-0700 [INFO] agent.auth.handler: renewed auth token 2023-03-22T13:41:53.877-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:41:53.877-0700 [DEBUG] agent.cache.leasecache: storing response into the cache: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:41:53.877-0700 [DEBUG] agent.cache.leasecache: initiating renewal: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:41:53.877-0700 [DEBUG] (runner) receiving dependency vault.read(path/to/dynamic/secret) 2023-03-22T13:41:53.877-0700 [DEBUG] (runner) initiating run 2023-03-22T13:41:53.877-0700 [DEBUG] (runner) checking template 842ad7d3a2a51f618cfe1ee5c2bed1aa 2023-03-22T13:41:53.877-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:41:53.877-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:41:53.877-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:41:53.877-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew 2023-03-22T13:41:53.878-0700 [DEBUG] (runner) rendering "(dynamic)" => "./secret.txt" 2023-03-22T13:41:53.893-0700 [INFO] (runner) rendered "(dynamic)" => "./secret.txt" 2023-03-22T13:41:53.893-0700 [DEBUG] (runner) diffing and updating dependencies 2023-03-22T13:41:53.893-0700 [DEBUG] (runner) vault.read(path/to/dynamic/secret) is still needed 2023-03-22T13:41:53.893-0700 [DEBUG] (runner) watching 1 dependencies 2023-03-22T13:41:53.893-0700 [DEBUG] (runner) all templates rendered 2023-03-22T13:41:53.919-0700 [DEBUG] agent.cache.leasecache: secret renewed: path=/v1/path/to/dynamic/secret 2023-03-22T13:41:53.929-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:41:53.929-0700 [DEBUG] agent.cache.leasecache: storing response into the cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:41:53.929-0700 [DEBUG] agent.cache.leasecache: initiating renewal: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:41:53.968-0700 [DEBUG] agent.cache.leasecache: secret renewed: path=/v1/sys/leases/renew 2023-03-22T13:45:30.821-0700 [DEBUG] agent.cache.leasecache: secret renewed: path=/v1/path/to/dynamic/secret 2023-03-22T13:45:32.703-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:45:32.703-0700 [DEBUG] agent.cache.leasecache: returning cached response: path=/v1/sys/leases/renew 2023-03-22T13:45:33.564-0700 [DEBUG] agent.cache.leasecache: secret renewed: path=/v1/sys/leases/renew 2023-03-22T13:49:07.817-0700 [DEBUG] agent.cache.leasecache: secret renewed: path=/v1/path/to/dynamic/secret 2023-03-22T13:49:07.817-0700 [DEBUG] agent.cache.leasecache: renewal halted; evicting from cache: path=/v1/path/to/dynamic/secret 2023-03-22T13:49:07.817-0700 [DEBUG] agent.cache.leasecache: evicting index from cache: id=e8c92098d24cbecc64aaf3b023a24d0a1031bf8c23e7e603af38057595cda72c method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:49:11.478-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:49:11.478-0700 [DEBUG] agent.cache.leasecache: returning cached response: path=/v1/sys/leases/renew 2023-03-22T13:49:13.165-0700 [DEBUG] agent.cache.leasecache: secret renewed: path=/v1/sys/leases/renew 2023-03-22T13:49:13.165-0700 [DEBUG] agent.cache.leasecache: renewal halted; evicting from cache: path=/v1/sys/leases/renew 2023-03-22T13:49:13.165-0700 [DEBUG] agent.cache.leasecache: evicting index from cache: id=b494cab33b2fcc532d2434686155428372a101273ac836fa650908ced7b569cf method=PUT path=/v1/sys/leases/renew 2023-03-22T13:52:50.252-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:52:50.252-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:52:50.252-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:52:50.252-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew 2023-03-22T13:52:50.469-0700 [WARN] vault.read(path/to/dynamic/secret): failed to renew: Error making API request. URL: PUT http://127.0.0.1:8200/v1/sys/leases/renew Code: 400. Errors: * lease not found 2023-03-22T13:52:50.469-0700 [WARN] vault.read(path/to/dynamic/secret): renewer done (maybe the lease expired) 2023-03-22T13:52:50.469-0700 [INFO] agent.apiproxy: received request: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:52:50.469-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:52:50.469-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:52:50.469-0700 [DEBUG] agent.apiproxy.client: performing request: method=GET url=https://vault.local/v1/path/to/dynamic/secret 2023-03-22T13:52:51.276-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:52:51.277-0700 [DEBUG] agent.cache.leasecache: storing response into the cache: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:52:51.277-0700 [DEBUG] agent.cache.leasecache: initiating renewal: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:52:51.277-0700 [DEBUG] (runner) receiving dependency vault.read(path/to/dynamic/secret) 2023-03-22T13:52:51.277-0700 [DEBUG] (runner) initiating run 2023-03-22T13:52:51.277-0700 [DEBUG] (runner) checking template 842ad7d3a2a51f618cfe1ee5c2bed1aa 2023-03-22T13:52:51.277-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:52:51.277-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:52:51.277-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:52:51.277-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew 2023-03-22T13:52:51.278-0700 [DEBUG] (runner) rendering "(dynamic)" => "./secret.txt" 2023-03-22T13:52:51.294-0700 [INFO] (runner) rendered "(dynamic)" => "./secret.txt" 2023-03-22T13:52:51.294-0700 [DEBUG] (runner) diffing and updating dependencies 2023-03-22T13:52:51.294-0700 [DEBUG] (runner) vault.read(path/to/dynamic/secret) is still needed 2023-03-22T13:52:51.294-0700 [DEBUG] (runner) watching 1 dependencies 2023-03-22T13:52:51.294-0700 [DEBUG] (runner) all templates rendered 2023-03-22T13:52:51.315-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:52:51.315-0700 [DEBUG] agent.cache.leasecache: storing response into the cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:52:51.315-0700 [DEBUG] agent.cache.leasecache: initiating renewal: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:52:51.324-0700 [DEBUG] agent.cache.leasecache: secret renewed: path=/v1/path/to/dynamic/secret 2023-03-22T13:52:51.353-0700 [DEBUG] agent.cache.leasecache: secret renewed: path=/v1/sys/leases/renew 2023-03-22T13:56:22.968-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:56:22.969-0700 [DEBUG] agent.cache.leasecache: returning cached response: path=/v1/sys/leases/renew 2023-03-22T13:56:28.736-0700 [DEBUG] agent.cache.leasecache: secret renewed: path=/v1/path/to/dynamic/secret 2023-03-22T13:56:30.158-0700 [DEBUG] agent.cache.leasecache: secret renewed: path=/v1/sys/leases/renew 2023-03-22T13:59:54.622-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:59:54.622-0700 [DEBUG] agent.cache.leasecache: returning cached response: path=/v1/sys/leases/renew ==> Vault Agent shutdown triggered 2023-03-22T13:59:58.378-0700 [INFO] agent.auth.handler: shutdown triggered, stopping lifetime watcher 2023-03-22T13:59:58.378-0700 [INFO] agent.sink.server: sink server stopped 2023-03-22T13:59:58.378-0700 [INFO] agent: sinks finished, exiting 2023-03-22T13:59:58.378-0700 [DEBUG] agent.cache.leasecache: context cancelled; stopping lifetime watcher: path=/v1/sys/leases/renew 2023-03-22T13:59:58.378-0700 [INFO] agent.auth.handler: auth handler stopped 2023-03-22T13:59:58.378-0700 [DEBUG] agent.cache.leasecache: context cancelled; stopping lifetime watcher: path=/v1/path/to/dynamic/secret 2023-03-22T13:59:58.378-0700 [INFO] (runner) stopping 2023-03-22T13:59:58.378-0700 [DEBUG] (runner) stopping watcher 2023-03-22T13:59:58.378-0700 [DEBUG] (watcher) stopping all views 2023-03-22T13:59:58.378-0700 [INFO] agent.template.server: template server stopped 2023-03-22T13:59:58.378-0700 [DEBUG] agent: would have sent systemd notification (systemd not present): notification=STOPPING=1 2023-03-22T13:59:58.378-0700 [INFO] (runner) received finish ```

From the above log, the following events are noteworthy:

After fetching the secret, the Template engine's LifetimeWatcher attempts the first lease renewal and the result is cached:

2023-03-22T13:41:53.877-0700 [INFO]  agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew
2023-03-22T13:41:53.877-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew
2023-03-22T13:41:53.877-0700 [INFO]  agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew
2023-03-22T13:41:53.877-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew
...
2023-03-22T13:41:53.929-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=PUT path=/v1/sys/leases/renew
2023-03-22T13:41:53.929-0700 [DEBUG] agent.cache.leasecache: storing response into the cache: method=PUT path=/v1/sys/leases/renew

The next time the Template server attempts to renew the lease, the request is served from the cache:

2023-03-22T13:45:32.703-0700 [INFO]  agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew
2023-03-22T13:45:32.703-0700 [DEBUG] agent.cache.leasecache: returning cached response: path=/v1/sys/leases/renew

The last renewal attempt from the Template server before the lease expires:

2023-03-22T13:49:11.478-0700 [INFO]  agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew
2023-03-22T13:49:11.478-0700 [DEBUG] agent.cache.leasecache: returning cached response: path=/v1/sys/leases/renew

Two seconds later, the Lease Cache terminates its renewal loop as the lease is approaching its max_ttl:

2023-03-22T13:49:13.165-0700 [DEBUG] agent.cache.leasecache: secret renewed: path=/v1/sys/leases/renew
2023-03-22T13:49:13.165-0700 [DEBUG] agent.cache.leasecache: renewal halted; evicting from cache: path=/v1/sys/leases/renew
2023-03-22T13:49:13.165-0700 [DEBUG] agent.cache.leasecache: evicting index from cache: id=b494cab33b2fcc532d2434686155428372a101273ac836fa650908ced7b569cf method=PUT path=/v1/sys/leases/renew

It takes another 3 minutes 37 seconds before the Template server attempts another lease renewal. By this time, the lease has expired, so the request results in an error.


2023-03-22T13:52:50.252-0700 [INFO]  agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew
2023-03-22T13:52:50.252-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew
2023-03-22T13:52:50.252-0700 [INFO]  agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew
2023-03-22T13:52:50.252-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew
2023-03-22T13:52:50.469-0700 [WARN] vault.read(path/to/dynamic/secret): failed to renew: Error making API request.

URL: PUT http://127.0.0.1:8200/v1/sys/leases/renew Code: 400. Errors:

lease not found 2023-03-22T13:52:50.469-0700 [WARN] vault.read(path/to/dynamic/secret): renewer done (maybe the lease expired)

The new secret is immediately fetched and rendered.

2023-03-22T13:52:51.294-0700 [INFO] (runner) rendered "(dynamic)" => "./secret.txt"

This resulted in a 10 minutes 57.4 second period between rendering the first and second secrets, even though the original secret expired after 10 minutes.

Expected behavior

The Vault Agent should reliably re-render templates containing dynamic secrets before the existing secrets' leases expire. Based on the implementation of LifetimeWatcher, we should expect templates to be re-rendered at least TTL * 0.10 seconds before the max_ttl is reached.

Environment

Vault Agent Version: v1.13.0
Server Operating System/Architecture: Linux/x86_64

[^1]: Though unrelated to this bug, this doubles the number of renewal requests sent to the Vault server, since both the Lease Cache and the Template server (via consul-template) are attempting to keep the lease renewed. [^2]: The Lease Cache will actually spawn another LifetimeWatcher renewal loop for the v1/sys/leases/renew response, separate from the original secret request, so the renewal request load on the Vault server is in fact tripled.

VioletHynes commented 1 year ago

Hi there,

The use_auto_auth_token configuration should only affect requests sent to Vault Agent's listener (i.e. using the API proxy). I didn't find a usage of the Vault Agent listener (proxying Vault's API) in the reproduction steps that might be using this configuration.

Could you confirm whether or not you're sending API requests directly to Vault Agent as part of this reproduction? Alternatively, could you confirm whether or not you're still seeing this bug with the use_auto_auth_token config set to false?

Notably, we log using auto auth token at DEBUG level when the use_auto_auth_token comes into play, which I don't see here, so I think it's very likely that this configuration does not play a part, like you think.

I think this might be another case of #16439 / #19227, which wouldn't require the cache or use_auto_auth_token at all, but I'd like to confirm, first.

Thanks, Violet

greghensley commented 1 year ago

Hi, Violet.

I agree, those two issues you linked appear to have the same root-cause. Notably, I see that the author of #16439 observed that they run their Agents with use_auto_auth_token=true and pointed to the LeaseCache as a possible culprit.

Could you confirm whether or not you're sending API requests directly to Vault Agent as part of this reproduction?

No requests are being sent to the Agent's listener. All requests are coming from the Template server's consul-template instance, inside the Agent.

Notably, we log using auto auth token at DEBUG level when the use_auto_auth_token comes into play, which I don't see here, so I think it's very likely that this configuration does not play a part, like you think.

That message is logged only when the request does not already contain a token.

Requests for templates already contain a token. Every time the auto-auth system gets a fresh token, that token is sent to the template system, which then restarts all its consul-template instances with the new token.

could you confirm whether or not you're still seeing this bug with the use_auto_auth_token config set to false?

In my testing, toggling use_auto_auth_token is all that is necessary to reproduce the broken refresh behavior.

Agent log with use_auto_auth_token disabled

``` ==> Vault Agent configuration: Api Address 1: http://127.0.0.1:8100 Api Address 2: http://bufconn Cgo: disabled Log Level: debug Version: Vault v1.13.0, built 2023-03-01T14:58:13Z Version Sha: a4cf0dc4437de35fce4860857b64569d092a9b5a+CHANGES 2023-03-22T13:27:08.668-0700 [DEBUG] agent: would have sent systemd notification (systemd not present): notification=READY=1 2023-03-22T13:27:08.668-0700 [INFO] agent.template.server: starting template server 2023-03-22T13:27:08.668-0700 [INFO] (runner) creating new runner (dry: false, once: false) 2023-03-22T13:27:08.668-0700 [INFO] agent.sink.server: starting sink server 2023-03-22T13:27:08.668-0700 [INFO] agent.auth.handler: starting auth handler 2023-03-22T13:27:08.668-0700 [INFO] agent.auth.handler: authenticating 2023-03-22T13:27:08.669-0700 [DEBUG] (runner) final config: {"Consul":{"Address":"","Namespace":"","Auth":{"Enabled":false,"Username":""},"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true},"SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":false,"Key":"","ServerName":"","Verify":true},"Token":"","TokenFile":"","Transport":{"CustomDialer":null,"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":13,"TLSHandshakeTimeout":10000000000}},"Dedup":{"Enabled":false,"MaxStale":2000000000,"Prefix":"consul-template/dedup/","TTL":15000000000,"BlockQueryWaitTime":60000000000},"DefaultDelims":{"Left":null,"Right":null},"Exec":{"Command":[],"Enabled":false,"Env":{"Denylist":[],"Custom":[],"Pristine":false,"Allowlist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":0},"KillSignal":2,"LogLevel":"DEBUG","FileLog":{"LogFilePath":"","LogRotateBytes":0,"LogRotateDuration":86400000000000,"LogRotateMaxFiles":0},"MaxStale":2000000000,"PidFile":"","ReloadSignal":1,"Syslog":{"Enabled":false,"Facility":"LOCAL0","Name":"consul-template"},"Templates":[{"Backup":false,"Command":[],"CommandTimeout":30000000000,"Contents":"{{- with secret \"path/to/dynamic/secret\" }}\n{{- scratch.MapSet \"secret\" \"request_id\" .RequestID }}\n{{- scratch.MapSet \"secret\" \"lease_id\" .LeaseID }}\n{{- scratch.MapSet \"secret\" \"lease_duration\" .LeaseDuration }}\n{{- scratch.MapSet \"secret\" \"renewable\" .Renewable }} \n{{- scratch.Get \"secret\" | toJSONPretty }}\n{{- end }}\n","CreateDestDirs":true,"Destination":"./secret.txt","ErrMissingKey":false,"ErrFatal":true,"Exec":{"Command":[],"Enabled":false,"Env":{"Denylist":[],"Custom":[],"Pristine":false,"Allowlist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":30000000000},"Perms":0,"User":null,"Uid":null,"Group":null,"Gid":null,"Source":"","Wait":{"Enabled":false,"Min":0,"Max":0},"LeftDelim":"","RightDelim":"","FunctionDenylist":[],"SandboxPath":""}],"TemplateErrFatal":null,"Vault":{"Address":"http://127.0.0.1:8200","Enabled":true,"Namespace":"","RenewToken":false,"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true},"SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":false,"Key":"","ServerName":"","Verify":false},"Transport":{"CustomDialer":{},"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":13,"TLSHandshakeTimeout":10000000000},"UnwrapToken":false,"DefaultLeaseDuration":300000000000,"LeaseRenewalThreshold":0.9,"K8SAuthRoleName":"","K8SServiceAccountTokenPath":"/run/secrets/kubernetes.io/serviceaccount/token","K8SServiceAccountToken":"","K8SServiceMountPath":"kubernetes"},"Nomad":{"Address":"","Enabled":false,"Namespace":"","SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":false,"Key":"","ServerName":"","Verify":true},"AuthUsername":"","AuthPassword":"","Transport":{"CustomDialer":null,"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":13,"TLSHandshakeTimeout":10000000000},"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true}},"Wait":{"Enabled":false,"Min":0,"Max":0},"Once":false,"ParseOnly":false,"BlockQueryWaitTime":60000000000} 2023-03-22T13:27:08.669-0700 [INFO] (runner) creating watcher 2023-03-22T13:27:08.698-0700 [INFO] agent.auth.handler: authentication successful, sending token to sinks 2023-03-22T13:27:08.699-0700 [INFO] agent.auth.handler: starting renewal process 2023-03-22T13:27:08.699-0700 [INFO] agent.template.server: template server received new token 2023-03-22T13:27:08.699-0700 [INFO] (runner) stopping 2023-03-22T13:27:08.699-0700 [DEBUG] (runner) stopping watcher 2023-03-22T13:27:08.699-0700 [DEBUG] (watcher) stopping all views 2023-03-22T13:27:08.699-0700 [INFO] (runner) creating new runner (dry: false, once: false) 2023-03-22T13:27:08.699-0700 [DEBUG] (runner) final config: {"Consul":{"Address":"","Namespace":"","Auth":{"Enabled":false,"Username":""},"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true},"SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":false,"Key":"","ServerName":"","Verify":true},"Token":"","TokenFile":"","Transport":{"CustomDialer":null,"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":13,"TLSHandshakeTimeout":10000000000}},"Dedup":{"Enabled":false,"MaxStale":2000000000,"Prefix":"consul-template/dedup/","TTL":15000000000,"BlockQueryWaitTime":60000000000},"DefaultDelims":{"Left":null,"Right":null},"Exec":{"Command":[],"Enabled":false,"Env":{"Denylist":[],"Custom":[],"Pristine":false,"Allowlist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":0},"KillSignal":2,"LogLevel":"DEBUG","FileLog":{"LogFilePath":"","LogRotateBytes":0,"LogRotateDuration":86400000000000,"LogRotateMaxFiles":0},"MaxStale":2000000000,"PidFile":"","ReloadSignal":1,"Syslog":{"Enabled":false,"Facility":"LOCAL0","Name":"consul-template"},"Templates":[{"Backup":false,"Command":[],"CommandTimeout":30000000000,"Contents":"{{- with secret \"path/to/dynamic/secret\" }}\n{{- scratch.MapSet \"secret\" \"request_id\" .RequestID }}\n{{- scratch.MapSet \"secret\" \"lease_id\" .LeaseID }}\n{{- scratch.MapSet \"secret\" \"lease_duration\" .LeaseDuration }}\n{{- scratch.MapSet \"secret\" \"renewable\" .Renewable }} \n{{- scratch.Get \"secret\" | toJSONPretty }}\n{{- end }}\n","CreateDestDirs":true,"Destination":"./secret.txt","ErrMissingKey":false,"ErrFatal":true,"Exec":{"Command":[],"Enabled":false,"Env":{"Denylist":[],"Custom":[],"Pristine":false,"Allowlist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":30000000000},"Perms":0,"User":null,"Uid":null,"Group":null,"Gid":null,"Source":"","Wait":{"Enabled":false,"Min":0,"Max":0},"LeftDelim":"","RightDelim":"","FunctionDenylist":[],"SandboxPath":""}],"TemplateErrFatal":null,"Vault":{"Address":"http://127.0.0.1:8200","Enabled":true,"Namespace":"","RenewToken":false,"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true},"SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":false,"Key":"","ServerName":"","Verify":false},"Transport":{"CustomDialer":{},"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":13,"TLSHandshakeTimeout":10000000000},"UnwrapToken":false,"DefaultLeaseDuration":300000000000,"LeaseRenewalThreshold":0.9,"K8SAuthRoleName":"","K8SServiceAccountTokenPath":"/run/secrets/kubernetes.io/serviceaccount/token","K8SServiceAccountToken":"","K8SServiceMountPath":"kubernetes"},"Nomad":{"Address":"","Enabled":false,"Namespace":"","SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":false,"Key":"","ServerName":"","Verify":true},"AuthUsername":"","AuthPassword":"","Transport":{"CustomDialer":null,"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":13,"TLSHandshakeTimeout":10000000000},"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true}},"Wait":{"Enabled":false,"Min":0,"Max":0},"Once":false,"ParseOnly":false,"BlockQueryWaitTime":60000000000} 2023-03-22T13:27:08.699-0700 [INFO] (runner) creating watcher 2023-03-22T13:27:08.699-0700 [INFO] (runner) starting 2023-03-22T13:27:08.699-0700 [DEBUG] (runner) running initial templates 2023-03-22T13:27:08.699-0700 [DEBUG] (runner) initiating run 2023-03-22T13:27:08.699-0700 [DEBUG] (runner) checking template 842ad7d3a2a51f618cfe1ee5c2bed1aa 2023-03-22T13:27:08.699-0700 [DEBUG] (runner) missing data for 1 dependencies 2023-03-22T13:27:08.699-0700 [DEBUG] (runner) missing dependency: vault.read(path/to/dynamic/secret) 2023-03-22T13:27:08.699-0700 [DEBUG] (runner) add used dependency vault.read(path/to/dynamic/secret) to missing since isLeader but do not have a watcher 2023-03-22T13:27:08.699-0700 [DEBUG] (runner) was not watching 1 dependencies 2023-03-22T13:27:08.699-0700 [DEBUG] (watcher) adding vault.read(path/to/dynamic/secret) 2023-03-22T13:27:08.699-0700 [DEBUG] (runner) diffing and updating dependencies 2023-03-22T13:27:08.699-0700 [DEBUG] (runner) watching 1 dependencies 2023-03-22T13:27:08.699-0700 [INFO] agent.apiproxy: received request: method=GET path=/v1/sys/internal/ui/mounts/path/to/dynamic/secret 2023-03-22T13:27:08.699-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=GET path=/v1/sys/internal/ui/mounts/path/to/dynamic/secret 2023-03-22T13:27:08.700-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=GET path=/v1/sys/internal/ui/mounts/path/to/dynamic/secret 2023-03-22T13:27:08.700-0700 [DEBUG] agent.apiproxy.client: performing request: method=GET url=https://vault.local/v1/sys/internal/ui/mounts/path/to/dynamic/secret 2023-03-22T13:27:08.728-0700 [DEBUG] agent.cache.leasecache: pass-through response; secret not renewable: method=GET path=/v1/sys/internal/ui/mounts/path/to/dynamic/secret 2023-03-22T13:27:08.728-0700 [INFO] agent.apiproxy: received request: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:27:08.728-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:27:08.728-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:27:08.728-0700 [DEBUG] agent.apiproxy.client: performing request: method=GET url=https://vault.local/v1/path/to/dynamic/secret 2023-03-22T13:27:08.740-0700 [INFO] agent.auth.handler: renewed auth token 2023-03-22T13:27:09.132-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:27:09.132-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:27:09.132-0700 [DEBUG] (runner) receiving dependency vault.read(path/to/dynamic/secret) 2023-03-22T13:27:09.132-0700 [DEBUG] (runner) initiating run 2023-03-22T13:27:09.132-0700 [DEBUG] (runner) checking template 842ad7d3a2a51f618cfe1ee5c2bed1aa 2023-03-22T13:27:09.132-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:27:09.133-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:27:09.133-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:27:09.133-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew 2023-03-22T13:27:09.133-0700 [DEBUG] (runner) rendering "(dynamic)" => "./secret.txt" 2023-03-22T13:27:09.148-0700 [INFO] (runner) rendered "(dynamic)" => "./secret.txt" 2023-03-22T13:27:09.148-0700 [DEBUG] (runner) diffing and updating dependencies 2023-03-22T13:27:09.148-0700 [DEBUG] (runner) vault.read(path/to/dynamic/secret) is still needed 2023-03-22T13:27:09.148-0700 [DEBUG] (runner) watching 1 dependencies 2023-03-22T13:27:09.148-0700 [DEBUG] (runner) all templates rendered 2023-03-22T13:27:09.168-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:27:09.168-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:30:42.843-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:30:42.843-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:30:42.843-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:30:42.843-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew 2023-03-22T13:30:42.994-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:30:42.994-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:34:16.670-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:34:16.670-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:34:16.670-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:34:16.670-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew 2023-03-22T13:34:16.844-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:34:16.844-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:34:16.844-0700 [WARN] vault.read(path/to/dynamic/secret): TTL of "5m" exceeded the effective max_ttl of "2m53s"; TTL value is capped accordingly 2023-03-22T13:36:25.851-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:36:25.851-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:36:25.851-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:36:25.851-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew 2023-03-22T13:36:26.107-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:36:26.107-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:36:26.107-0700 [WARN] vault.read(path/to/dynamic/secret): TTL of "5m" exceeded the effective max_ttl of "43s"; TTL value is capped accordingly 2023-03-22T13:36:26.107-0700 [WARN] vault.read(path/to/dynamic/secret): renewer done (maybe the lease expired) 2023-03-22T13:36:26.107-0700 [INFO] agent.apiproxy: received request: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:36:26.107-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:36:26.107-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:36:26.107-0700 [DEBUG] agent.apiproxy.client: performing request: method=GET url=https://vault.local/v1/path/to/dynamic/secret 2023-03-22T13:36:26.453-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:36:26.453-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:36:26.453-0700 [DEBUG] (runner) receiving dependency vault.read(path/to/dynamic/secret) 2023-03-22T13:36:26.453-0700 [DEBUG] (runner) initiating run 2023-03-22T13:36:26.453-0700 [DEBUG] (runner) checking template 842ad7d3a2a51f618cfe1ee5c2bed1aa 2023-03-22T13:36:26.453-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:36:26.453-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:36:26.453-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:36:26.453-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew 2023-03-22T13:36:26.454-0700 [DEBUG] (runner) rendering "(dynamic)" => "./secret.txt" 2023-03-22T13:36:26.470-0700 [INFO] (runner) rendered "(dynamic)" => "./secret.txt" 2023-03-22T13:36:26.470-0700 [DEBUG] (runner) diffing and updating dependencies 2023-03-22T13:36:26.470-0700 [DEBUG] (runner) vault.read(path/to/dynamic/secret) is still needed 2023-03-22T13:36:26.470-0700 [DEBUG] (runner) watching 1 dependencies 2023-03-22T13:36:26.470-0700 [DEBUG] (runner) all templates rendered 2023-03-22T13:36:26.489-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:36:26.489-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:39:59.776-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:39:59.776-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:39:59.776-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:39:59.776-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew 2023-03-22T13:39:59.933-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:39:59.933-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:43:33.220-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:43:33.220-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:43:33.220-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:43:33.220-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew 2023-03-22T13:43:33.378-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:43:33.378-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:43:33.379-0700 [WARN] vault.read(path/to/dynamic/secret): TTL of "5m" exceeded the effective max_ttl of "2m53s"; TTL value is capped accordingly 2023-03-22T13:45:41.999-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:45:41.999-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:45:41.999-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:45:41.999-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew 2023-03-22T13:45:42.131-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:45:42.131-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:45:42.131-0700 [WARN] vault.read(path/to/dynamic/secret): TTL of "5m" exceeded the effective max_ttl of "44s"; TTL value is capped accordingly 2023-03-22T13:45:42.131-0700 [WARN] vault.read(path/to/dynamic/secret): renewer done (maybe the lease expired) 2023-03-22T13:45:42.131-0700 [INFO] agent.apiproxy: received request: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:45:42.131-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:45:42.131-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:45:42.131-0700 [DEBUG] agent.apiproxy.client: performing request: method=GET url=https://vault.local/v1/path/to/dynamic/secret 2023-03-22T13:45:42.511-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:45:42.511-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:45:42.512-0700 [DEBUG] (runner) receiving dependency vault.read(path/to/dynamic/secret) 2023-03-22T13:45:42.512-0700 [DEBUG] (runner) initiating run 2023-03-22T13:45:42.512-0700 [DEBUG] (runner) checking template 842ad7d3a2a51f618cfe1ee5c2bed1aa 2023-03-22T13:45:42.512-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:45:42.512-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:45:42.512-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:45:42.512-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew 2023-03-22T13:45:42.513-0700 [DEBUG] (runner) rendering "(dynamic)" => "./secret.txt" 2023-03-22T13:45:42.529-0700 [INFO] (runner) rendered "(dynamic)" => "./secret.txt" 2023-03-22T13:45:42.529-0700 [DEBUG] (runner) diffing and updating dependencies 2023-03-22T13:45:42.529-0700 [DEBUG] (runner) vault.read(path/to/dynamic/secret) is still needed 2023-03-22T13:45:42.529-0700 [DEBUG] (runner) watching 1 dependencies 2023-03-22T13:45:42.529-0700 [DEBUG] (runner) all templates rendered 2023-03-22T13:45:42.554-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:45:42.554-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:49:19.568-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:49:19.568-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:49:19.568-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:49:19.569-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew 2023-03-22T13:49:19.701-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:49:19.701-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:52:56.713-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:52:56.713-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:52:56.713-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:52:56.713-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew 2023-03-22T13:52:56.830-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:52:56.830-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:52:56.830-0700 [WARN] vault.read(path/to/dynamic/secret): TTL of "5m" exceeded the effective max_ttl of "2m46s"; TTL value is capped accordingly 2023-03-22T13:52:56.830-0700 [WARN] vault.read(path/to/dynamic/secret): renewer done (maybe the lease expired) 2023-03-22T13:52:56.830-0700 [INFO] agent.apiproxy: received request: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:52:56.830-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:52:56.830-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:52:56.830-0700 [DEBUG] agent.apiproxy.client: performing request: method=GET url=https://vault.local/v1/path/to/dynamic/secret 2023-03-22T13:52:57.215-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:52:57.215-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T13:52:57.216-0700 [DEBUG] (runner) receiving dependency vault.read(path/to/dynamic/secret) 2023-03-22T13:52:57.216-0700 [DEBUG] (runner) initiating run 2023-03-22T13:52:57.216-0700 [DEBUG] (runner) checking template 842ad7d3a2a51f618cfe1ee5c2bed1aa 2023-03-22T13:52:57.216-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:52:57.216-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:52:57.216-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:52:57.216-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew 2023-03-22T13:52:57.216-0700 [DEBUG] (runner) rendering "(dynamic)" => "./secret.txt" 2023-03-22T13:52:57.233-0700 [INFO] (runner) rendered "(dynamic)" => "./secret.txt" 2023-03-22T13:52:57.233-0700 [DEBUG] (runner) diffing and updating dependencies 2023-03-22T13:52:57.233-0700 [DEBUG] (runner) vault.read(path/to/dynamic/secret) is still needed 2023-03-22T13:52:57.233-0700 [DEBUG] (runner) watching 1 dependencies 2023-03-22T13:52:57.233-0700 [DEBUG] (runner) all templates rendered 2023-03-22T13:52:57.262-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:52:57.262-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:56:30.527-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:56:30.527-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:56:30.527-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:56:30.527-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew 2023-03-22T13:56:30.669-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=PUT path=/v1/sys/leases/renew 2023-03-22T13:56:30.669-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=PUT path=/v1/sys/leases/renew 2023-03-22T14:00:03.935-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T14:00:03.935-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T14:00:03.935-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew 2023-03-22T14:00:03.935-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew 2023-03-22T14:00:04.083-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=PUT path=/v1/sys/leases/renew 2023-03-22T14:00:04.083-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=PUT path=/v1/sys/leases/renew 2023-03-22T14:00:04.083-0700 [WARN] vault.read(path/to/dynamic/secret): TTL of "5m" exceeded the effective max_ttl of "2m53s"; TTL value is capped accordingly 2023-03-22T14:02:12.682-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T14:02:12.682-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T14:02:12.682-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew 2023-03-22T14:02:12.682-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew 2023-03-22T14:02:12.839-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=PUT path=/v1/sys/leases/renew 2023-03-22T14:02:12.839-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=PUT path=/v1/sys/leases/renew 2023-03-22T14:02:12.839-0700 [WARN] vault.read(path/to/dynamic/secret): TTL of "5m" exceeded the effective max_ttl of "45s"; TTL value is capped accordingly 2023-03-22T14:02:12.839-0700 [WARN] vault.read(path/to/dynamic/secret): renewer done (maybe the lease expired) 2023-03-22T14:02:12.839-0700 [INFO] agent.apiproxy: received request: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T14:02:12.839-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T14:02:12.839-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T14:02:12.839-0700 [DEBUG] agent.apiproxy.client: performing request: method=GET url=https://vault.local/v1/path/to/dynamic/secret 2023-03-22T14:02:13.173-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T14:02:13.174-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=GET path=/v1/path/to/dynamic/secret 2023-03-22T14:02:13.174-0700 [DEBUG] (runner) receiving dependency vault.read(path/to/dynamic/secret) 2023-03-22T14:02:13.174-0700 [DEBUG] (runner) initiating run 2023-03-22T14:02:13.174-0700 [DEBUG] (runner) checking template 842ad7d3a2a51f618cfe1ee5c2bed1aa 2023-03-22T14:02:13.174-0700 [INFO] agent.apiproxy: received request: method=PUT path=/v1/sys/leases/renew 2023-03-22T14:02:13.174-0700 [DEBUG] agent.cache.leasecache: forwarding request from cache: method=PUT path=/v1/sys/leases/renew 2023-03-22T14:02:13.174-0700 [INFO] agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew 2023-03-22T14:02:13.174-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew 2023-03-22T14:02:13.174-0700 [DEBUG] (runner) rendering "(dynamic)" => "./secret.txt" 2023-03-22T14:02:13.181-0700 [INFO] (runner) rendered "(dynamic)" => "./secret.txt" 2023-03-22T14:02:13.181-0700 [DEBUG] (runner) diffing and updating dependencies 2023-03-22T14:02:13.181-0700 [DEBUG] (runner) vault.read(path/to/dynamic/secret) is still needed 2023-03-22T14:02:13.181-0700 [DEBUG] (runner) watching 1 dependencies 2023-03-22T14:02:13.181-0700 [DEBUG] (runner) all templates rendered 2023-03-22T14:02:13.209-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=PUT path=/v1/sys/leases/renew 2023-03-22T14:02:13.209-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=PUT path=/v1/sys/leases/renew ==> Vault Agent shutdown triggered 2023-03-22T14:03:46.378-0700 [INFO] (runner) stopping 2023-03-22T14:03:46.378-0700 [DEBUG] (runner) stopping watcher 2023-03-22T14:03:46.378-0700 [DEBUG] (watcher) stopping all views 2023-03-22T14:03:46.378-0700 [INFO] agent.template.server: template server stopped 2023-03-22T14:03:46.378-0700 [INFO] agent.auth.handler: shutdown triggered, stopping lifetime watcher 2023-03-22T14:03:46.378-0700 [INFO] agent.auth.handler: auth handler stopped 2023-03-22T14:03:46.378-0700 [INFO] agent.sink.server: sink server stopped 2023-03-22T14:03:46.378-0700 [INFO] agent: sinks finished, exiting 2023-03-22T14:03:46.378-0700 [DEBUG] agent: would have sent systemd notification (systemd not present): notification=STOPPING=1 2023-03-22T14:03:46.378-0700 [INFO] (runner) received finish ```

In this log, you can see that the LeaseCache is enabled and operational, but is explicitly not caching responses to the Template server's requests because the Vault token is unknown to the LeaseCache:

2023-03-22T13:30:42.843-0700 [INFO]  agent.apiproxy: forwarding request to Vault: method=PUT path=/v1/sys/leases/renew   
2023-03-22T13:30:42.843-0700 [DEBUG] agent.apiproxy.client: performing request: method=PUT url=https://vault.local/v1/sys/leases/renew
2023-03-22T13:30:42.994-0700 [DEBUG] agent.cache.leasecache: processing lease response: method=PUT path=/v1/sys/leases/renew
2023-03-22T13:30:42.994-0700 [DEBUG] agent.cache.leasecache: pass-through lease response; token not managed by agent: method=PUT path=/v1/sys/leases/renew

The LeaseCache will only know about the auto-auth token when use_auto_auth_token is enabled. When the flag is enabled, an inmemSink is created and registered with the auto-auth system. Besides providing a means to retrieve the auto-auth token when attaching it to proxied requests, the inmemSink also registers new auto-auth tokens in the LeaseCache whenever a new token is created.

greghensley commented 1 year ago

It makes sense that the LeaseCache would need to know about the auto-auth token when the API Proxy is being used from outside the Agent (via a listener), since you probably want those unauthenticated requests' secrets to be cached and auto-renewed by the LeaseCache.

This problem with template refreshing only happens because the Template's LifetimeWatcher is not getting a realistic picture of the remaining lifetime on lease, because the Agent's LeaseCache is sending back a cached response from sys/leases/renew.

In fact, I suspect that we would also see this problem with an external client, since any well-behaved Vault client should be attempting to renew their own leases. If an external client were to use the Proxy with caching enabled, and authenticated via the Proxy (so the LeaseCache knows about the client's token), the LeaseCache would be sending the cached renewal response back to the external client. In fact, I would expect to see this even without the use_auto_auth_token option, since the LeaseCache would know about the client's token (and so invoke caching) regardless of the configuration option.

Actually, I decided to just go ahead and test this with an external client. My suspicion was correct: with only a listener and caching enabled (no templates and no auto-auth at all), an external client attempting to use sys/leases/renew will be receive cached responses from the LeaseCache, leading the client to believe that the lease is being renewed for the full TTL even if the lease is about to expire.

greghensley commented 1 year ago

Brain-storming some possible solutions:

The LeaseCache could explicitly exclude responses from sys/leases/renew (or from any sys/* API) from being cached. This would ensure that all attempts to renew a lease through the proxy hit the Vault server and get a real response. Counter-arguments:
1. The Vault server would still see twice the normal renewal requests, since both the template/client and the LeaseCache would be renewing the secrets.
2. I believe there would still be a race when a new secret is being requested, since the LeaseCache is depending on a LifetimeWatcher to trigger cache eviction. With the random jitter introduced by the LifetimeWatcher, it's possible that the template/client could exit its renewal loop before the LeaseCache. If that happens, then the template/client would attempt to fetch a new secret via the Proxy but would still be served the cached secret response (which is about to expire).
Instead of passing the auto-auth token to the Template system, generate an additional child token. The child token would not be written to any Sinks, so the LeaseCache would not be aware of it. Counter-arguments:
1. This would solve the problem for the Template system, since the LeaseCache would not cache leases from the unrecognized token. However, it does not solve the issue for external clients that are routed through the Proxy but still expect to manage their own leases.
The report in #19227 suggests making the LifetimeWatcher aware of the Age header which is injected by the LeaseCache. Even if we ignore the logistics of getting the HTTP headers piped back into the LifetimeWatcher, I don't think this would solve anything. The LifetimeWatcher depends on seeing the TTL in the renewal response get progressively truncated, indicating that the lease is approaching expiration and cannot be extended. If the LeaseCache is returning a cached renewal response, it's going to continue returning that same cached TTL even as the Age grows larger than that cached TTL. Therefore, the LifetimeWatcher cannot infer how close the lease is to final expiration based on only the Age and original (cached) TTL value. To be sure, I verified that, yes, the LeaseCache is recording Age as the time since the original cache entry, not the time since the last renewal, so LifetimeWatcher cannot infer the remaining lease time from only the default TTL and the Age header.

rivedty commented 1 year ago

is there any workaround? Also experiencing this behavior when trying to use persistent cache between vault init and vault agent sidecar in kubernetes environment.


    "auto_auth" = {
      "method" = {
        "mount_path" = "auth/k8s"
        "config" = {
          "role" = "k8s_role"
        }
        "type" = "kubernetes"
      }

      "sink" = {
        "config" = {
          "path" = "/home/vault/.token"
        }

        "type" = "file"
      }
    }

    "exit_after_auth" = true
    "pid_file" = "/home/vault/.pid"

    "vault" = {
      "address" = "https://vault-address.com"
    }

    cache {
      use_auto_auth_token = true
      persist "kubernetes" {
        path = "/vault/secrets"
      }
    }

    "template" = {
      "contents" = <<CONFIG
    {
      {{- with secret "test/database/creds/test" -}}
      "ConnectionStrings": {
          "Default": "server=test.privatelink.database.windows.net;Database=test-db;User Id={{ .Data.username }};Password={{ .Data.password }};Trust Server Certificate=true"
      },
      {{- end }}
    }
    CONFIG
      "destination" = "/vault/secrets/appsettings.json"
    }
`

heatherezell commented 7 months ago

Hi folks! Is this still an issue in newer versions of Vault? Please let me know so I can bubble it up accordingly. Thanks!

busser commented 6 months ago

@hsimon-hashicorp Yes, I am currently seeing this behaviour with Vault 1.15.4.

ozozgun commented 3 months ago

@hsimon-hashicorp I have the same config as @rivedty and I have the same issue between sidecar and initcontainer with vault version 1.15.4. https://github.com/hashicorp/vault/issues/27739

hashicorp / vault