hashicorp / consul-template

Template rendering, notifier, and supervisor for @HashiCorp Consul and Vault data.
https://www.hashicorp.com/
Mozilla Public License 2.0
4.76k stars 782 forks source link

Secrets not updating #1423

Open phemmer opened 3 years ago

phemmer commented 3 years ago

Consul Template version

consul-template v0.25.1 (b11fa800)

Configuration

consul {
    address = "192.168.122.1:8500"
    token = "abcd1234"
}
vault {
    address = "http://192.168.122.1:8200"
    token = "abcd1234"
}
template {
    source = "/tmp/test.ctmpl"
    destination = "/tmp/test.out"
}
{{ key "mykey" }}
{{ secret "secret/mysecret" }}

Consul mykey:

123

Vault mysecret:

{"foo":"bar1"}

Command

consul-template -config test.hcl -dry -log-level=trace

Debug output

2020/11/04 04:06:06.747863 [INFO] consul-template v0.25.1 (b11fa800)
2020/11/04 04:06:06.747897 [INFO] (runner) creating new runner (dry: true, once: false)
2020/11/04 04:06:06.748100 [DEBUG] (runner) final config: {"Consul":{"Address":"192.168.122.1:8500","Namespace":"","Auth":{"Enabled":false,"Username":"","Password":""},"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true},"SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":false,"Key":"","ServerName":"","Verify":true},"Token":"","Transport":{"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":4,"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":"trace","MaxStale":2000000000,"PidFile":"","ReloadSignal":1,"Syslog":{"Enabled":false,"Facility":"LOCAL0","Name":"consul-template"},"Templates":[{"Backup":false,"Command":"","CommandTimeout":30000000000,"Contents":"","CreateDestDirs":true,"Destination":"/tmp/test.out","ErrMissingKey":false,"Exec":{"Command":"","Enabled":false,"Env":{"Denylist":[],"Custom":[],"Pristine":false,"Allowlist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":30000000000},"Perms":0,"Source":"/tmp/test.ctmpl","Wait":{"Enabled":false,"Min":0,"Max":0},"LeftDelim":"","RightDelim":"","FunctionDenylist":[],"SandboxPath":""}],"Vault":{"Address":"http://192.168.122.1:8200","Enabled":true,"Namespace":"","RenewToken":true,"Retry":{"Attempts":12,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true},"SSL":{"CaCert":"","CaPath":"","Cert":"","Enabled":true,"Key":"","ServerName":"","Verify":true},"Transport":{"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":4,"TLSHandshakeTimeout":10000000000},"UnwrapToken":false},"Wait":{"Enabled":false,"Min":0,"Max":0},"Once":false,"BlockQueryWaitTime":60000000000}
2020/11/04 04:06:06.748150 [INFO] (runner) creating watcher
2020/11/04 04:06:06.748164 [DEBUG] (watcher) adding vault.token
2020/11/04 04:06:06.748170 [TRACE] (watcher) vault.token starting
2020/11/04 04:06:06.748271 [TRACE] (view) vault.token starting fetch
2020/11/04 04:06:06.748298 [TRACE] vault.token: starting renewer
2020/11/04 04:06:06.748410 [INFO] (runner) starting
2020/11/04 04:06:06.748420 [DEBUG] (runner) running initial templates
2020/11/04 04:06:06.748459 [DEBUG] (runner) initiating run
2020/11/04 04:06:06.748773 [DEBUG] (runner) checking template bcaf102ae0995d5b6c74b5a06d739b62
2020/11/04 04:06:06.749426 [DEBUG] (runner) missing data for 2 dependencies
2020/11/04 04:06:06.749562 [DEBUG] (runner) missing dependency: kv.block(mykey)
2020/11/04 04:06:06.749656 [DEBUG] (runner) missing dependency: vault.read(secret/mysecret)
2020/11/04 04:06:06.749733 [DEBUG] (runner) add used dependency kv.block(mykey) to missing since isLeader but do not have a watcher
2020/11/04 04:06:06.749810 [DEBUG] (runner) add used dependency vault.read(secret/mysecret) to missing since isLeader but do not have a watcher
2020/11/04 04:06:06.749897 [DEBUG] (runner) was not watching 2 dependencies
2020/11/04 04:06:06.749975 [DEBUG] (watcher) adding kv.block(mykey)
2020/11/04 04:06:06.750124 [TRACE] (watcher) kv.block(mykey) starting
2020/11/04 04:06:06.750238 [DEBUG] (watcher) adding vault.read(secret/mysecret)
2020/11/04 04:06:06.750432 [TRACE] (watcher) vault.read(secret/mysecret) starting
2020/11/04 04:06:06.750539 [DEBUG] (runner) diffing and updating dependencies
2020/11/04 04:06:06.750711 [DEBUG] (runner) watching 3 dependencies
2020/11/04 04:06:06.750368 [TRACE] (view) kv.block(mykey) starting fetch
2020/11/04 04:06:06.751002 [TRACE] kv.block(mykey): GET /v1/kv/mykey?stale=true&wait=1m0s
2020/11/04 04:06:06.751151 [TRACE] vault.token: successfully renewed
2020/11/04 04:06:06.751167 [WARN] vault.token: TTL of "765h9m" exceeded the effective max_ttl of "765h8m44s"; TTL value is capped accordingly
2020/11/04 04:06:06.750633 [TRACE] (view) vault.read(secret/mysecret) starting fetch
2020/11/04 04:06:06.752394 [TRACE] kv.block(mykey): returned "123"
2020/11/04 04:06:06.752542 [TRACE] (view) kv.block(mykey) marking successful data response
2020/11/04 04:06:06.752660 [TRACE] (view) kv.block(mykey) successful contact, resetting retries
2020/11/04 04:06:06.753292 [TRACE] vault.read(secret/mysecret): GET /v1/secret/data/mysecret
2020/11/04 04:06:06.754572 [TRACE] vault.read(secret/mysecret): non-renewable secret, set sleep for 4m41.002254161s
2020/11/04 04:06:06.754675 [TRACE] (view) vault.read(secret/mysecret) marking successful data response
2020/11/04 04:06:06.754803 [TRACE] (view) vault.read(secret/mysecret) successful contact, resetting retries
2020/11/04 04:06:06.851697 [TRACE] (view) kv.block(mykey) received data
2020/11/04 04:06:06.851794 [TRACE] (view) kv.block(mykey) starting fetch
2020/11/04 04:06:06.851835 [TRACE] kv.block(mykey): GET /v1/kv/mykey?index=247529&stale=true&wait=1m0s
2020/11/04 04:06:06.852029 [DEBUG] (runner) receiving dependency kv.block(mykey)
2020/11/04 04:06:06.852038 [DEBUG] (runner) initiating run
2020/11/04 04:06:06.852042 [DEBUG] (runner) checking template bcaf102ae0995d5b6c74b5a06d739b62
2020/11/04 04:06:06.852382 [DEBUG] (runner) missing data for 1 dependencies
2020/11/04 04:06:06.852393 [DEBUG] (runner) missing dependency: vault.read(secret/mysecret)
2020/11/04 04:06:06.852402 [DEBUG] (runner) missing data for 1 dependencies
2020/11/04 04:06:06.852405 [DEBUG] (runner) diffing and updating dependencies
2020/11/04 04:06:06.852410 [DEBUG] (runner) kv.block(mykey) is still needed
2020/11/04 04:06:06.852413 [DEBUG] (runner) vault.read(secret/mysecret) is still needed
2020/11/04 04:06:06.852418 [DEBUG] (runner) watching 3 dependencies
2020/11/04 04:06:06.870780 [TRACE] (view) vault.read(secret/mysecret) received data
2020/11/04 04:06:06.870920 [DEBUG] (runner) receiving dependency vault.read(secret/mysecret)
2020/11/04 04:06:06.870946 [DEBUG] (runner) initiating run
2020/11/04 04:06:06.870957 [DEBUG] (runner) checking template bcaf102ae0995d5b6c74b5a06d739b62
2020/11/04 04:06:06.871052 [TRACE] (view) vault.read(secret/mysecret) starting fetch
2020/11/04 04:06:06.871529 [DEBUG] (runner) rendering "/tmp/test.ctmpl" => "/tmp/test.out"
> /tmp/test.out
123
{d95a71b9-c6ab-fed5-cc1a-44c2bf2080b4  0 false map[data:map[foo:bar1] metadata:map[created_time:2020-11-04T04:06:00.22861827Z deletion_time: destroyed:false version:5]] [] <nil> <nil>}
2020/11/04 04:06:06.871618 [INFO] (runner) rendered "/tmp/test.ctmpl" => "/tmp/test.out"
2020/11/04 04:06:06.871627 [DEBUG] (runner) diffing and updating dependencies
2020/11/04 04:06:06.871638 [DEBUG] (runner) kv.block(mykey) is still needed
2020/11/04 04:06:06.871647 [DEBUG] (runner) vault.read(secret/mysecret) is still needed
2020/11/04 04:06:06.871657 [DEBUG] (runner) watching 3 dependencies
2020/11/04 04:06:06.871665 [DEBUG] (runner) all templates rendered
2020/11/04 04:06:19.843032 [TRACE] kv.block(mykey): returned "1234"
2020/11/04 04:06:19.843063 [TRACE] (view) kv.block(mykey) marking successful data response
2020/11/04 04:06:19.843078 [TRACE] (view) kv.block(mykey) successful contact, resetting retries
2020/11/04 04:06:19.843243 [TRACE] (view) kv.block(mykey) received data
2020/11/04 04:06:19.843486 [DEBUG] (runner) receiving dependency kv.block(mykey)
2020/11/04 04:06:19.843515 [DEBUG] (runner) initiating run
2020/11/04 04:06:19.843522 [DEBUG] (runner) checking template bcaf102ae0995d5b6c74b5a06d739b62
2020/11/04 04:06:19.843772 [TRACE] (view) kv.block(mykey) starting fetch
2020/11/04 04:06:19.843916 [DEBUG] (runner) rendering "/tmp/test.ctmpl" => "/tmp/test.out"
> /tmp/test.out
1234
{d95a71b9-c6ab-fed5-cc1a-44c2bf2080b4  0 false map[data:map[foo:bar1] metadata:map[created_time:2020-11-04T04:06:00.22861827Z deletion_time: destroyed:false version:5]] [] <nil> <nil>}
2020/11/04 04:06:19.843984 [INFO] (runner) rendered "/tmp/test.ctmpl" => "/tmp/test.out"
2020/11/04 04:06:19.843993 [DEBUG] (runner) diffing and updating dependencies
2020/11/04 04:06:19.844002 [DEBUG] (runner) kv.block(mykey) is still needed
2020/11/04 04:06:19.844012 [DEBUG] (runner) vault.read(secret/mysecret) is still needed
2020/11/04 04:06:19.844022 [DEBUG] (runner) watching 3 dependencies
2020/11/04 04:06:19.844030 [DEBUG] (runner) all templates rendered
2020/11/04 04:06:19.844225 [TRACE] kv.block(mykey): GET /v1/kv/mykey?index=247530&stale=true&wait=1m0s

Expected behavior

Secret value should have updated

Actual behavior

Secret value remained unchanged

Steps to reproduce

  1. Create new Vault secret version for mysecret and set to {"foo":"bar2"}.
  2. Change value of Consul key mykey to 1234.

Additional info

I'm assuming there's some caching going on here. While the documentation does state:

Consul Template will not immediately reload in the event a secret is changed as it does with Consul's key-value store.

...it does not make it clear that the secret will not reload even if something else in the template triggers a render. If this is deliberate behavior, can we please get a mechanism for busting the cache.

phemmer commented 3 years ago

After a bunch of experimentation, I found an evil workaround:

{{ with key "mykey" }}
{{ secret (print "secret/mysecret?version=-" . }}
{{ end }}

This passes mykey as a negative version number. Vault seems to ignore negative version numbers and retrieves the latest value. However consul-template doesn't know this and uses it as the cache key.

eikenb commented 3 years ago

Hey @phemmer, thanks for taking the time to file this ticket.

The behavior is as intended as each value being monitored separately and triggers the template when it gets a new value, using the new value for it and cached values for all other entries. That is when a the monitoring process finds an update, it updates the value in the cache and triggers the template.

So what is needed here is a way to force trigger a value fetch when another one is triggered. Basically an indirect dependency. This dependency relationship needs to be specified and stored somehow, either in the template or in the config. Currently leaning toward in the template as that's where other dependencies are expressed.

otto-dev commented 1 year ago

If you change a secret using vault kv put, the render output stays the same. Even if you manually re-render the template, it uses the cached version. This can't be the intended behavior? That's what I observe in my Nomad template blocks which are written to file.

Changing a secret that's used in a template should trigger the template. It doesn't.

Rendering a template afresh should use the latest value from the vault. Also not the case.

That means you can never change a secret used in consul-template.

otto-dev commented 1 year ago

The Renew API tries to use most of the time the secret is good, renewing at around 90% of the lease time (as set by Vault).

My guess would be that the bug is because the Renewer thinks the old secret still has life left and there is no need to refresh it (even if changed in vault). Hence you are stuck on the old secret for X amount of time. I don't know if X is finite.

Wnthr commented 1 year ago

If you change a secret using vault kv put, the render output stays the same. Even if you manually re-render the template, it uses the cached version. This can't be the intended behavior? That's what I observe in my Nomad template blocks which are written to file.

So what it sounds like you are saying is that in a template with 100 different items, everytime one of them changes, all 100 should be refreshed? That is not clear to me to be the intended result at all in a caching system, but maybe I am missing something. The original response seems to indicate that all the values are indeed cached individually, and that not getting all the cached values is indeed intended behavior, and is what I would expect from a cache.

The functionality provided is not a cache of grouped values that go together on the template level, where all values would be updated on the individual secret level, and the process on invalidating one secret and triggering the template engine to put whatever is in the cache in our respective files is wholly separate from figuring out that a value changes in vault, no?

Changing a secret that's used in a template should trigger the template. It doesn't.

"Trigger the template" should indeed happen, but the triggering of the template should read the cached values (of which 99 are the same, and the one that actually changed is now populating that cache, from which said template is triggering? It seems as it does, as soon as the change detector realizes a value has changed, does it not?

Rendering a template afresh should use the latest value from the vault. Also not the case.

I would like to be able to have a brute force trigger available to invalidate the cache and force consul-template to re-read all secrets, but that seems to be easiest done by sending a SIGHUP to the consul-template. We might want that as an option inside of a template, but that seems like a different issue than what should be the normal behavior. It seems to me that as long as consul-template thinks a value in the cache is valid, it should use that instead of querying the original source?

Of course, that could trigger a discussion about whether the algorithm to figure out when a value is updated needs looking at, but that seems a wholly different discussion from whether the templates render correctly, doesn't it? If there is data on this not working as intended, I would be interested to see it.

That means you can never change a secret used in consul-template.

That doesn't seem to follow, though. If you again, have these 100 values in the template that change, going through those secrets and checking for updates will be done on a schedule that defaults to "once every five minutes", my tests using two variables seem to indicate that I have the new updated versions of those secrets in the template output file within 5 minutes of changing them, and indeed, when setting the value of default_lease_duration to 30s instead, it does have all my new values in the file within those 30s.

What is seems to me, is that caching on the secret level is (and should be) per individual secret, not per template, and that renewal of those values happens (and should happen) within the constraints of the renewal system as configured. If I change my values, I will have those updates reflected in the output file for a given template within default_lease_duration.

If I am missing some erroneous behavior that you have experienced (I have not done any testing on the consul or nomad kv engines, for instance), please give some more specific information about what the conditions of that error is, so we can take a look and figure out what is going on. In the meantime, it seems to me after some testing that I will have to agree with @eikenb:

The behavior is as intended as each value being monitored separately and triggers the template when it gets a new value, using the new value for it and cached values for all other entries. That is when a the monitoring process finds an update, it updates the value in the cache and triggers the template.