Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Vault Agent lease cache interferes with template refresh for dynamic secrets #19684

Open
greghensley opened this issue Mar 22, 2023 · 8 comments
Open

Vault Agent lease cache interferes with template refresh for dynamic secrets #19684

greghensley opened this issue Mar 22, 2023 · 8 comments
Labels
agent bug Used to indicate a potential bug

Comments

@greghensley
Copy link

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     = <<EOF                                                                                                   
{{- with secret "path/to/dynamic/secret" }}                                                                              
{{- .Data | toJSONPretty }}                                                                                              
{{- end }}                                                                                                               
EOF                                                                                                                      
  destination  = "./secret.txt"                                                                                          
}                                                                                                                        
                                                                                                                         
auto_auth {                                                                                                              
  method {                                                                                                               
    type = "token_file"                                                                                                  
    config = {                                                                                                           
      token_file_path = "$HOME/.vault-token"                                                                             
    }                                                                                                                    
  }                                                                                                                      
}                                                                                                                        
                                                                                                                         
cache {}                                                                                                                 
                                                                                                                         
api_proxy {                                                                                                              
  use_auto_auth_token = true                                                                                             
}                                                                                                                        
                                                                                                                         
listener "unix" {                                                                                                        
  address = "./vault.sock"                                                                                               
  tls_disable = true                                                                                                     
}
  1. Configure a dynamic secret on a Vault Server with a short TTL and Maximum TTL (recommend 5m TTL and 10m MaxTTL).
  2. Login with sufficient rights to fetch the secret and renew leases.
  3. 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

Footnotes

  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
Copy link
Contributor

VioletHynes commented Mar 24, 2023 •
edited
Loading

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
Copy link
Author

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
Copy link
Author

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
Copy link
Author

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 api.LifeTimeWatcher is not aware of Age headers #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
Copy link

rivedty commented May 30, 2023 •
edited
Loading

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
Copy link
Contributor

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
Copy link

busser commented Apr 2, 2024

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

@busser busser mentioned this issue Apr 2, 2024
Open
@ozozgun
Copy link

ozozgun commented Jul 10, 2024 •
edited
Loading

@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.
#27739

@heatherezell heatherezell added agent bug Used to indicate a potential bug and removed waiting-for-response labels Jul 15, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
agent bug Used to indicate a potential bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
6 participants
@VioletHynes @greghensley @busser @heatherezell @rivedty @ozozgun