Vault KV Secrets since 0.21.1 causes endless rendering of template

[lawliet89]

Consul Template version

0.21.2

Configuration

pid_file = "/pid/consul-template"
log_level = "info"
kill_signal = "SIGTERM"

vault {
  address = "http://127.0.0.1:8100"
  vault_agent_token_file = "/vault/token"

  ssl {
    enabled = true
    ca_cert = "/vault_ca/ca.pem"
  }
}

template {
  source = "/template/config.template.hcl"
  destination = "/output/config.hcl"
  create_dest_dirs = true
  error_on_missing_key = true

  command = "/bin/sh -c 'kill -1 $(cat /pid/app) || echo \"not running\"'"
}

template {
  contents = <<EOF
{{- key "apps/xxx/cluster_config_hcl" -}}
EOF

  destination = "/output/cluster_config_data.hcl"
  create_dest_dirs = true
  error_on_missing_key = true

  command = "/bin/sh -c 'kill -1 $(cat /pid/app) || echo \"not running\"'"
}

Template is a bunch of reads from Consul KV and Vault KV V2

Debug output

The log is an endless sequence of re-rendering.

E 2019-09-04T07:37:08.073444678Z 2019/09/04 07:37:08.073314 [DEBUG] (runner) receiving dependency vault.read(kv/_app/sendgrid)
 
E 2019-09-04T07:37:08.073467285Z 2019/09/04 07:37:08.073330 [DEBUG] (runner) initiating run
 
E 2019-09-04T07:37:08.073473410Z 2019/09/04 07:37:08.073335 [DEBUG] (runner) checking template cd4eb212446d2146ac52730ec8822a70
 
E 2019-09-04T07:37:08.081545651Z 2019/09/04 07:37:08.081401 [DEBUG] (runner) rendering "/template/config.template.hcl" => "/output/config.hcl"
 
E 2019-09-04T07:37:08.081561990Z 2019/09/04 07:37:08.081479 [DEBUG] (runner) checking template 314c5ce0120813609a37cc38463f8eb5
 
E 2019-09-04T07:37:08.081871327Z 2019/09/04 07:37:08.081769 [DEBUG] (runner) rendering "(dynamic)" => "/output/cluster_config_data.hcl"
 
E 2019-09-04T07:37:08.081888057Z 2019/09/04 07:37:08.081848 [DEBUG] (runner) diffing and updating dependencies
 
E 2019-09-04T07:37:08.081894179Z 2019/09/04 07:37:08.081859 [DEBUG] (runner) kv.get(apps/vault/service_address) is still needed
 
E 2019-09-04T07:37:08.081912721Z 2019/09/04 07:37:08.081865 [DEBUG] (runner) kv.block(apps/database/set_role) is still needed
 
E 2019-09-04T07:37:08.081918556Z 2019/09/04 07:37:08.081870 [DEBUG] (runner) kv.get(apps/tracemalloc/enable) is still needed
 
E 2019-09-04T07:37:08.081924041Z 2019/09/04 07:37:08.081884 [DEBUG] (runner) vault.read(kv/_app/sendgrid) is still needed
 
E 2019-09-04T07:37:08.081930021Z 2019/09/04 07:37:08.081893 [DEBUG] (runner) kv.get(apps/monitor_image) is still needed
 
E 2019-09-04T07:37:08.081935552Z 2019/09/04 07:37:08.081897 [DEBUG] (runner) kv.get(apps/helm_chart_repo) is still needed
 
E 2019-09-04T07:37:08.081940577Z 2019/09/04 07:37:08.081901 [DEBUG] (runner) vault.read(kv/_app/internal_jwt/keys) is still needed
 
E 2019-09-04T07:37:08.081959030Z 2019/09/04 07:37:08.081906 [DEBUG] (runner) kv.block(apps/auth/audience) is still needed
 
E 2019-09-04T07:37:08.081964790Z 2019/09/04 07:37:08.081919 [DEBUG] (runner) kv.block(apps/database/uri) is still needed
 
E 2019-09-04T07:37:08.081970957Z 2019/09/04 07:37:08.081924 [DEBUG] (runner) kv.get(apps/sqlalchemy_track_modifications) is still needed
 
E 2019-09-04T07:37:08.081976535Z 2019/09/04 07:37:08.081928 [DEBUG] (runner) kv.get(apps/database/timeout) is still needed
 
E 2019-09-04T07:37:08.081982004Z 2019/09/04 07:37:08.081932 [DEBUG] (runner) kv.block(apps/vault/kv_path) is still needed
 
E 2019-09-04T07:37:08.082002534Z 2019/09/04 07:37:08.081944 [DEBUG] (runner) kv.block(apps/cors/origins) is still needed
 
E 2019-09-04T07:37:08.082008383Z 2019/09/04 07:37:08.081949 [DEBUG] (runner) kv.get(apps/deployment/helm_image) is still needed
 
E 2019-09-04T07:37:08.082027040Z 2019/09/04 07:37:08.081954 [DEBUG] (runner) kv.block(apps/auth/access_token_params) is still needed
 
E 2019-09-04T07:37:08.082033267Z 2019/09/04 07:37:08.081959 [DEBUG] (runner) kv.get(apps/mail/default_sender_address) is still needed
 
E 2019-09-04T07:37:08.082038331Z 2019/09/04 07:37:08.081971 [DEBUG] (runner) kv.block(apps/cluster_config_hcl) is still needed
 
E 2019-09-04T07:37:08.082043321Z 2019/09/04 07:37:08.081979 [DEBUG] (runner) kv.block(apps/database/vault_path) is still needed
 
E 2019-09-04T07:37:08.082048325Z 2019/09/04 07:37:08.081984 [DEBUG] (runner) kv.block(apps/span_domain) is still needed
 
E 2019-09-04T07:37:08.082052991Z 2019/09/04 07:37:08.081988 [DEBUG] (runner) vault.read(kv/_app/internal_jwt/whitelist) is still needed
 
E 2019-09-04T07:37:08.082057918Z 2019/09/04 07:37:08.081999 [DEBUG] (runner) kv.block(apps/vault/agent_address) is still needed
 
E 2019-09-04T07:37:08.082063255Z 2019/09/04 07:37:08.082008 [DEBUG] (runner) kv.block(apps/auth/realm) is still needed
 
E 2019-09-04T07:37:08.082068528Z 2019/09/04 07:37:08.082014 [DEBUG] (runner) kv.block(apps/auth/disable) is still needed
 
E 2019-09-04T07:37:08.082074069Z 2019/09/04 07:37:08.082019 [DEBUG] (runner) kv.block(apps/auth/issuer) is still needed
 
E 2019-09-04T07:37:08.082088916Z 2019/09/04 07:37:08.082023 [DEBUG] (runner) kv.block(apps/auth/algorithms) is still needed
 
E 2019-09-04T07:37:08.082094189Z 2019/09/04 07:37:08.082037 [DEBUG] (runner) vault.read(kv/_app/oidc) is still needed
 
E 2019-09-04T07:37:08.082099122Z 2019/09/04 07:37:08.082042 [DEBUG] (runner) kv.get(apps/mail/enable) is still needed
 
E 2019-09-04T07:37:08.082104300Z 2019/09/04 07:37:08.082047 [DEBUG] (runner) kv.block(apps/vault/app_base) is still needed
 
E 2019-09-04T07:37:08.082109580Z 2019/09/04 07:37:08.082051 [DEBUG] (runner) kv.block(apps/auth/client_id) is still needed
 
E 2019-09-04T07:37:08.082115112Z 2019/09/04 07:37:08.082061 [DEBUG] (runner) kv.get(apps/notification/enabled) is still needed
 
E 2019-09-04T07:37:08.082120843Z 2019/09/04 07:37:08.082065 [DEBUG] (runner) kv.get(apps/sentry/dsn) is still needed
 
E 2019-09-04T07:37:08.082126265Z 2019/09/04 07:37:08.082070 [DEBUG] (runner) kv.get(apps/jaeger/sampler/type) is still needed
 
E 2019-09-04T07:37:08.082131261Z 2019/09/04 07:37:08.082075 [DEBUG] (runner) kv.block(apps/database/database) is still needed
 
E 2019-09-04T07:37:08.082146697Z 2019/09/04 07:37:08.082086 [DEBUG] (runner) kv.get(apps/monitor_image_memory_limit) is still needed
 
E 2019-09-04T07:37:08.082158760Z 2019/09/04 07:37:08.082094 [DEBUG] (runner) kv.get(apps/deployment/deployment_job_cluster_namespace) is still needed
 
E 2019-09-04T07:37:08.082164512Z 2019/09/04 07:37:08.082099 [DEBUG] (runner) kv.get(apps/jaeger/sampler/param) is still needed
 
E 2019-09-04T07:37:08.082169734Z 2019/09/04 07:37:08.082104 [DEBUG] (runner) kv.get(apps/mail/sendgrid_credentials_vault_path) is still needed
 
E 2019-09-04T07:37:08.082175047Z 2019/09/04 07:37:08.082116 [DEBUG] (runner) watching 38 dependencies
 
E 2019-09-04T07:37:08.082180157Z 2019/09/04 07:37:08.082121 [DEBUG] (runner) all templates rendered
 
E 2019-09-04T07:37:08.082193225Z 2019/09/04 07:37:08.082132 [DEBUG] (runner) receiving dependency vault.read(kv/_app/oidc)
 
E 2019-09-04T07:37:08.082198239Z 2019/09/04 07:37:08.082148 [DEBUG] (runner) receiving dependency vault.read(kv/_app/internal_jwt/whitelist)
 
E 2019-09-04T07:37:08.082203331Z 2019/09/04 07:37:08.082165 [DEBUG] (runner) receiving dependency vault.read(kv/_app/internal_jwt/keys)
 
E 2019-09-04T07:37:08.082208922Z 2019/09/04 07:37:08.082170 [DEBUG] (runner) initiating run
 
E 2019-09-04T07:37:08.082214290Z 2019/09/04 07:37:08.082174 [DEBUG] (runner) checking template cd4eb212446d2146ac52730ec8822a70
 
E 2019-09-04T07:37:08.084507185Z 2019/09/04 07:37:08.084382 [DEBUG] (runner) rendering "/template/config.template.hcl" => "/output/config.hcl"
 
E 2019-09-04T07:37:08.084527964Z 2019/09/04 07:37:08.084445 [DEBUG] (runner) checking template 314c5ce0120813609a37cc38463f8eb5
 
E 2019-09-04T07:37:08.084780944Z 2019/09/04 07:37:08.084699 [DEBUG] (runner) rendering "(dynamic)" => "/output/cluster_config_data.hcl"
 
E 2019-09-04T07:37:08.084972402Z 2019/09/04 07:37:08.084914 [DEBUG] (runner) diffing and updating dependencies
 
E 2019-09-04T07:37:08.084984522Z 2019/09/04 07:37:08.084927 [DEBUG] (runner) kv.block(apps/database/database) is still needed
 
E 2019-09-04T07:37:08.085037171Z 2019/09/04 07:37:08.084931 [DEBUG] (runner) kv.get(apps/sqlalchemy_track_modifications) is still needed
 
E 2019-09-04T07:37:08.085042937Z 2019/09/04 07:37:08.084956 [DEBUG] (runner) kv.get(apps/vault/service_address) is still needed
 
E 2019-09-04T07:37:08.085046651Z 2019/09/04 07:37:08.084961 [DEBUG] (runner) kv.get(apps/sentry/dsn) is still needed
 
E 2019-09-04T07:37:08.085058274Z 2019/09/04 07:37:08.084965 [DEBUG] (runner) vault.read(kv/_app/sendgrid) is still needed
 
E 2019-09-04T07:37:08.085062228Z 2019/09/04 07:37:08.084969 [DEBUG] (runner) kv.block(apps/database/uri) is still needed
 
E 2019-09-04T07:37:08.085065720Z 2019/09/04 07:37:08.084973 [DEBUG] (runner) kv.get(apps/database/timeout) is still needed
 
E 2019-09-04T07:37:08.085069421Z 2019/09/04 07:37:08.084977 [DEBUG] (runner) vault.read(kv/_app/internal_jwt/keys) is still needed
 
E 2019-09-04T07:37:08.085085624Z 2019/09/04 07:37:08.084981 [DEBUG] (runner) kv.block(apps/cors/origins) is still needed
 
E 2019-09-04T07:37:08.085089411Z 2019/09/04 07:37:08.084985 [DEBUG] (runner) kv.block(apps/auth/client_id) is still needed
 
E 2019-09-04T07:37:08.085092981Z 2019/09/04 07:37:08.084989 [DEBUG] (runner) kv.block(apps/auth/realm) is still needed
 
E 2019-09-04T07:37:08.085096733Z 2019/09/04 07:37:08.084993 [DEBUG] (runner) kv.get(apps/mail/enable) is still needed
 
E 2019-09-04T07:37:08.085100465Z 2019/09/04 07:37:08.084997 [DEBUG] (runner) kv.block(apps/vault/app_base) is still needed
 
E 2019-09-04T07:37:08.085104058Z 2019/09/04 07:37:08.085001 [DEBUG] (runner) kv.get(apps/monitor_image) is still needed
 
E 2019-09-04T07:37:08.085107526Z 2019/09/04 07:37:08.085004 [DEBUG] (runner) vault.read(kv/_app/internal_jwt/whitelist) is still needed
 
E 2019-09-04T07:37:08.085110984Z 2019/09/04 07:37:08.085008 [DEBUG] (runner) kv.block(apps/vault/kv_path) is still needed
 
E 2019-09-04T07:37:08.085115677Z 2019/09/04 07:37:08.085012 [DEBUG] (runner) kv.block(apps/auth/audience) is still needed
 
E 2019-09-04T07:37:08.085169605Z 2019/09/04 07:37:08.085032 [DEBUG] (runner) vault.read(kv/_app/oidc) is still needed
 
E 2019-09-04T07:37:08.085175329Z 2019/09/04 07:37:08.085036 [DEBUG] (runner) kv.block(apps/span_domain) is still needed
 
E 2019-09-04T07:37:08.085178943Z 2019/09/04 07:37:08.085041 [DEBUG] (runner) kv.get(apps/deployment/helm_image) is still needed
 
E 2019-09-04T07:37:08.085182417Z 2019/09/04 07:37:08.085045 [DEBUG] (runner) kv.block(apps/auth/disable) is still needed
 
E 2019-09-04T07:37:08.085185912Z 2019/09/04 07:37:08.085049 [DEBUG] (runner) kv.block(apps/auth/access_token_params) is still needed
 
E 2019-09-04T07:37:08.085189392Z 2019/09/04 07:37:08.085052 [DEBUG] (runner) kv.block(apps/database/set_role) is still needed
 
E 2019-09-04T07:37:08.085192973Z 2019/09/04 07:37:08.085056 [DEBUG] (runner) kv.block(apps/auth/issuer) is still needed
 
E 2019-09-04T07:37:08.085196355Z 2019/09/04 07:37:08.085060 [DEBUG] (runner) kv.get(apps/tracemalloc/enable) is still needed
 
E 2019-09-04T07:37:08.085199926Z 2019/09/04 07:37:08.085064 [DEBUG] (runner) kv.get(apps/mail/default_sender_address) is still needed
 
E 2019-09-04T07:37:08.085203531Z 2019/09/04 07:37:08.085067 [DEBUG] (runner) kv.block(apps/vault/agent_address) is still needed
 
E 2019-09-04T07:37:08.085207186Z 2019/09/04 07:37:08.085071 [DEBUG] (runner) kv.block(apps/auth/algorithms) is still needed
 
E 2019-09-04T07:37:08.085210676Z 2019/09/04 07:37:08.085075 [DEBUG] (runner) kv.get(apps/notification/enabled) is still needed
 
E 2019-09-04T07:37:08.085214135Z 2019/09/04 07:37:08.085078 [DEBUG] (runner) kv.get(apps/jaeger/sampler/param) is still needed
 
E 2019-09-04T07:37:08.085221996Z 2019/09/04 07:37:08.085082 [DEBUG] (runner) kv.block(apps/cluster_config_hcl) is still needed
 
E 2019-09-04T07:37:08.085225724Z 2019/09/04 07:37:08.085085 [DEBUG] (runner) kv.get(apps/monitor_image_memory_limit) is still needed
 
E 2019-09-04T07:37:08.085229226Z 2019/09/04 07:37:08.085090 [DEBUG] (runner) kv.get(apps/deployment/deployment_job_cluster_namespace) is still needed
 
E 2019-09-04T07:37:08.085233105Z 2019/09/04 07:37:08.085094 [DEBUG] (runner) kv.block(apps/database/vault_path) is still needed
 
E 2019-09-04T07:37:08.085236798Z 2019/09/04 07:37:08.085112 [DEBUG] (runner) kv.get(apps/helm_chart_repo) is still needed
 
E 2019-09-04T07:37:08.085240446Z 2019/09/04 07:37:08.085116 [DEBUG] (runner) kv.get(apps/jaeger/sampler/type) is still needed
 
E 2019-09-04T07:37:08.085243953Z 2019/09/04 07:37:08.085119 [DEBUG] (runner) kv.get(apps/mail/sendgrid_credentials_vault_path) is still needed
 
E 2019-09-04T07:37:08.085247506Z 2019/09/04 07:37:08.085124 [DEBUG] (runner) watching 38 dependencies
 
E 2019-09-04T07:37:08.085250892Z 2019/09/04 07:37:08.085128 [DEBUG] (runner) all templates rendered
 

Reverting back to 0.21.0 seems to fix the issue. I guess this has something to do with the Vault KV V2 changes introduced since 0.21.1.

The metrics also show a constant usage of CPU cycles by Consul Template.

[lawliet89]

I have a more minimal example to reproduce this.

Start Vault and Consul locally in -dev mode:

$ consul agent -server -dev
$ vault server -dev -dev-root-token-id=12345

# Write some secret to Vault
$ VAULT_ADDR='http://127.0.0.1:8200' vault kv put secret/foo bar=baz

Consider the following template

{{- with secret "secret/foo" }}
  {{- .Data.data.bar }}
{{- end }}

and configuration

consul {
}

vault {
  address = "http://127.0.0.1:8200"
  token = "12345"
  renew_token = false
}

template {
  source = "template.txt"
  destination = "out.txt"
}

log_level = "trace"

If we run consul-template -config config.hcl, it's an endless stream of:

2019/09/04 08:09:05.121712 [INFO] consul-template v0.21.1 (a96de954)
2019/09/04 08:09:05.121800 [INFO] (runner) creating new runner (dry: false, once: false)
2019/09/04 08:09:05.123125 [DEBUG] (runner) final config: {"Consul":{"Address":"","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":9,"TLSHandshakeTimeout":10000000000}},"Dedup":{"Enabled":false,"MaxStale":2000000000,"Prefix":"consul-template/dedup/","TTL":15000000000},"Exec":{"Command":"","Enabled":false,"Env":{"Blacklist":[],"Custom":[],"Pristine":false,"Whitelist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":0},"KillSignal":2,"LogLevel":"trace","MaxStale":2000000000,"PidFile":"","ReloadSignal":1,"Syslog":{"Enabled":false,"Facility":"LOCAL0"},"Templates":[{"Backup":false,"Command":"","CommandTimeout":30000000000,"Contents":"","CreateDestDirs":true,"Destination":"out.txt","ErrMissingKey":false,"Exec":{"Command":"","Enabled":false,"Env":{"Blacklist":[],"Custom":[],"Pristine":false,"Whitelist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":30000000000},"Perms":0,"Source":"template.txt","Wait":{"Enabled":false,"Min":0,"Max":0},"LeftDelim":"","RightDelim":"","FunctionBlacklist":null,"SandboxPath":""}],"Vault":{"Address":"http://127.0.0.1:8200","Enabled":true,"Grace":15000000000,"Namespace":"","RenewToken":false,"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":9,"TLSHandshakeTimeout":10000000000},"UnwrapToken":false},"Wait":{"Enabled":false,"Min":0,"Max":0},"Once":false}
2019/09/04 08:09:05.123306 [INFO] (runner) creating watcher
2019/09/04 08:09:05.123648 [INFO] (runner) starting
2019/09/04 08:09:05.123741 [DEBUG] (runner) running initial templates
2019/09/04 08:09:05.123765 [DEBUG] (runner) initiating run
2019/09/04 08:09:05.123900 [DEBUG] (runner) checking template 8b68f95ab9f9437dc77a2efb1a5d70a9
2019/09/04 08:09:05.124820 [DEBUG] (runner) was not watching 1 dependencies
2019/09/04 08:09:05.124905 [DEBUG] (watcher) adding vault.read(secret/foo)
2019/09/04 08:09:05.124938 [TRACE] (watcher) vault.read(secret/foo) starting
2019/09/04 08:09:05.125032 [DEBUG] (runner) diffing and updating dependencies
2019/09/04 08:09:05.125057 [DEBUG] (runner) watching 1 dependencies
2019/09/04 08:09:05.125157 [TRACE] (view) vault.read(secret/foo) starting fetch
2019/09/04 08:09:05.128682 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.130464 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m27.570013856s
2019/09/04 08:09:05.130510 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.130534 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.130550 [TRACE] (view) vault.read(secret/foo) received data
2019/09/04 08:09:05.130667 [TRACE] (view) vault.read(secret/foo) starting fetch
2019/09/04 08:09:05.130704 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.130768 [DEBUG] (runner) receiving dependency vault.read(secret/foo)
2019/09/04 08:09:05.130870 [DEBUG] (runner) initiating run
2019/09/04 08:09:05.130921 [DEBUG] (runner) checking template 8b68f95ab9f9437dc77a2efb1a5d70a9
2019/09/04 08:09:05.131560 [DEBUG] (runner) rendering "template.txt" => "out.txt"
2019/09/04 08:09:05.131682 [DEBUG] (runner) diffing and updating dependencies
2019/09/04 08:09:05.131708 [DEBUG] (runner) vault.read(secret/foo) is still needed
2019/09/04 08:09:05.131742 [DEBUG] (runner) watching 1 dependencies
2019/09/04 08:09:05.131778 [DEBUG] (runner) all templates rendered
2019/09/04 08:09:05.132235 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m32.478194935s
2019/09/04 08:09:05.132269 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.132284 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.132308 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.132439 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.133953 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m36.52137039s
2019/09/04 08:09:05.134053 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.134084 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.134113 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.134120 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.136165 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m26.131577648s
2019/09/04 08:09:05.136223 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.136258 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.136293 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.136441 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.138074 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m30.98336749s
2019/09/04 08:09:05.138145 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.138185 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.138235 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.138239 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.140122 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m18.908916458s
2019/09/04 08:09:05.140179 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.140215 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.140245 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.140249 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.141935 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m35.258706251s
2019/09/04 08:09:05.141988 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.142027 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.142077 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.142108 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.143150 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m34.347575882s
2019/09/04 08:09:05.143180 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.143191 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.143206 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.143328 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.144083 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m16.109393926s
2019/09/04 08:09:05.144111 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.144121 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.144137 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.144249 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.145107 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m23.380267881s
2019/09/04 08:09:05.145152 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.145163 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.145178 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.145435 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.146089 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m28.441397345s
2019/09/04 08:09:05.146110 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.146121 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.146138 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.146141 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.146969 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m17.805967084s
2019/09/04 08:09:05.146990 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.146999 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.147013 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.147095 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.147744 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m35.211015109s
2019/09/04 08:09:05.147766 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.147774 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.147784 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.147836 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.148372 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m30.285505797s
2019/09/04 08:09:05.148388 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.148394 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.148404 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.148486 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.149012 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m19.104226762s
2019/09/04 08:09:05.149035 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.149053 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.149070 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.149073 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.149854 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m29.997197948s
2019/09/04 08:09:05.149880 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.149898 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.149912 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.149915 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.150654 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m34.137785724s
2019/09/04 08:09:05.150675 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.150688 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.150704 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.150772 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.151387 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m23.530377074s
2019/09/04 08:09:05.151402 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.151428 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.151439 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.151447 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.152053 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m27.104393955s
2019/09/04 08:09:05.152081 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.152087 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.152094 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.152099 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.152604 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m16.656990675s
2019/09/04 08:09:05.152622 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.152636 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.152651 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.152655 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.153135 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m19.513373914s
2019/09/04 08:09:05.153153 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.153163 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.153174 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.153226 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.153678 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m23.156996591s
2019/09/04 08:09:05.153690 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.153696 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.153704 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.153770 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.154171 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m21.834980768s
2019/09/04 08:09:05.154190 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.154199 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.154212 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.154219 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.154719 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m40.04618393s
2019/09/04 08:09:05.154732 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.154738 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.154746 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.154805 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.155215 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m35.898409843s
2019/09/04 08:09:05.155229 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.155235 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.155244 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.155250 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.155741 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m32.544402407s
2019/09/04 08:09:05.155756 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.155762 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.155771 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.155827 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.156219 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m25.420926554s
2019/09/04 08:09:05.156231 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.156237 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.156245 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.156312 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.156748 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m40.318515986s
2019/09/04 08:09:05.156762 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.156767 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.156775 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.156831 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.157196 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m23.062253303s
2019/09/04 08:09:05.157206 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.157210 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.157217 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.157241 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.157584 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m37.903382084s
2019/09/04 08:09:05.157596 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.157601 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.157609 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.157662 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.157983 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m43.928010848s
2019/09/04 08:09:05.157995 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.158005 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.158012 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.158014 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.158399 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m44.922400567s
2019/09/04 08:09:05.158410 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.158417 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.158424 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.158426 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.158873 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m24.240316965s
2019/09/04 08:09:05.158885 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.158891 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.158900 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.158906 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.159293 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m23.222360063s
2019/09/04 08:09:05.159304 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.159308 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.159316 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.159370 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.159722 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m39.778667634s
2019/09/04 08:09:05.159733 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.159737 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.159744 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.159795 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.160136 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m35.002834248s
2019/09/04 08:09:05.160151 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.160157 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.160164 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.160232 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.160569 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m20.243193726s
2019/09/04 08:09:05.160582 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.160587 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.160598 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.160649 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.161088 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m34.670182043s
2019/09/04 08:09:05.161103 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.161110 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.161119 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.161147 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.161517 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m24.431767034s
2019/09/04 08:09:05.161529 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.161533 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.161541 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.161575 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.161945 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m20.147212377s
2019/09/04 08:09:05.161953 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.161958 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.161964 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.162015 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.162383 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m16.625513446s
2019/09/04 08:09:05.162397 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.162402 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.162409 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:09:05.162457 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:09:05.162882 [TRACE] vault.read(secret/foo): non-renewable secret, set sleep for 4m17.489770233s
2019/09/04 08:09:05.162893 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:09:05.162899 [TRACE] (view) vault.read(secret/foo) no new data (index was the same)
2019/09/04 08:09:05.162905 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo

<...>

With debug logging, we get

2019/09/04 08:11:12.098614 [INFO] consul-template v0.21.1 (a96de954)
2019/09/04 08:11:12.098653 [INFO] (runner) creating new runner (dry: false, once: false)
2019/09/04 08:11:12.099332 [DEBUG] (runner) final config: {"Consul":{"Address":"","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":9,"TLSHandshakeTimeout":10000000000}},"Dedup":{"Enabled":false,"MaxStale":2000000000,"Prefix":"consul-template/dedup/","TTL":15000000000},"Exec":{"Command":"","Enabled":false,"Env":{"Blacklist":[],"Custom":[],"Pristine":false,"Whitelist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":0},"KillSignal":2,"LogLevel":"debug","MaxStale":2000000000,"PidFile":"","ReloadSignal":1,"Syslog":{"Enabled":false,"Facility":"LOCAL0"},"Templates":[{"Backup":false,"Command":"","CommandTimeout":30000000000,"Contents":"","CreateDestDirs":true,"Destination":"out.txt","ErrMissingKey":false,"Exec":{"Command":"","Enabled":false,"Env":{"Blacklist":[],"Custom":[],"Pristine":false,"Whitelist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":30000000000},"Perms":0,"Source":"template.txt","Wait":{"Enabled":false,"Min":0,"Max":0},"LeftDelim":"","RightDelim":"","FunctionBlacklist":null,"SandboxPath":""}],"Vault":{"Address":"http://127.0.0.1:8200","Enabled":true,"Grace":15000000000,"Namespace":"","RenewToken":false,"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":9,"TLSHandshakeTimeout":10000000000},"UnwrapToken":false},"Wait":{"Enabled":false,"Min":0,"Max":0},"Once":false}
2019/09/04 08:11:12.099430 [INFO] (runner) creating watcher
2019/09/04 08:11:12.099643 [INFO] (runner) starting
2019/09/04 08:11:12.099693 [DEBUG] (runner) running initial templates
2019/09/04 08:11:12.099703 [DEBUG] (runner) initiating run
2019/09/04 08:11:12.099779 [DEBUG] (runner) checking template 8b68f95ab9f9437dc77a2efb1a5d70a9
2019/09/04 08:11:12.100417 [DEBUG] (runner) was not watching 1 dependencies
2019/09/04 08:11:12.100455 [DEBUG] (watcher) adding vault.read(secret/foo)
2019/09/04 08:11:12.100476 [DEBUG] (runner) diffing and updating dependencies
2019/09/04 08:11:12.100490 [DEBUG] (runner) watching 1 dependencies
2019/09/04 08:11:12.103938 [DEBUG] (runner) receiving dependency vault.read(secret/foo)
2019/09/04 08:11:12.103984 [DEBUG] (runner) initiating run
2019/09/04 08:11:12.104005 [DEBUG] (runner) checking template 8b68f95ab9f9437dc77a2efb1a5d70a9
2019/09/04 08:11:12.104350 [DEBUG] (runner) rendering "template.txt" => "out.txt"
2019/09/04 08:11:12.104408 [DEBUG] (runner) diffing and updating dependencies
2019/09/04 08:11:12.104417 [DEBUG] (runner) vault.read(secret/foo) is still needed
2019/09/04 08:11:12.104429 [DEBUG] (runner) watching 1 dependencies
2019/09/04 08:11:12.104435 [DEBUG] (runner) all templates rendered
2019/09/04 08:11:13.000129 [DEBUG] (runner) receiving dependency vault.read(secret/foo)
2019/09/04 08:11:13.000138 [DEBUG] (runner) initiating run
2019/09/04 08:11:13.000143 [DEBUG] (runner) checking template 8b68f95ab9f9437dc77a2efb1a5d70a9
2019/09/04 08:11:13.000288 [DEBUG] (runner) rendering "template.txt" => "out.txt"
2019/09/04 08:11:13.000328 [DEBUG] (runner) diffing and updating dependencies
2019/09/04 08:11:13.000335 [DEBUG] (runner) vault.read(secret/foo) is still needed
2019/09/04 08:11:13.000343 [DEBUG] (runner) watching 1 dependencies
2019/09/04 08:11:13.000349 [DEBUG] (runner) all templates rendered
2019/09/04 08:11:14.000066 [DEBUG] (runner) receiving dependency vault.read(secret/foo)
2019/09/04 08:11:14.000078 [DEBUG] (runner) initiating run
2019/09/04 08:11:14.000084 [DEBUG] (runner) checking template 8b68f95ab9f9437dc77a2efb1a5d70a9
2019/09/04 08:11:14.000270 [DEBUG] (runner) rendering "template.txt" => "out.txt"
2019/09/04 08:11:14.000308 [DEBUG] (runner) diffing and updating dependencies
2019/09/04 08:11:14.000315 [DEBUG] (runner) vault.read(secret/foo) is still needed
2019/09/04 08:11:14.000323 [DEBUG] (runner) watching 1 dependencies
2019/09/04 08:11:14.000327 [DEBUG] (runner) all templates rendered
2019/09/04 08:11:15.000248 [DEBUG] (runner) receiving dependency vault.read(secret/foo)
2019/09/04 08:11:15.000259 [DEBUG] (runner) initiating run
2019/09/04 08:11:15.000264 [DEBUG] (runner) checking template 8b68f95ab9f9437dc77a2efb1a5d70a9
2019/09/04 08:11:15.000381 [DEBUG] (runner) rendering "template.txt" => "out.txt"
2019/09/04 08:11:15.000411 [DEBUG] (runner) diffing and updating dependencies
2019/09/04 08:11:15.000418 [DEBUG] (runner) vault.read(secret/foo) is still needed
2019/09/04 08:11:15.000423 [DEBUG] (runner) watching 1 dependencies
2019/09/04 08:11:15.000426 [DEBUG] (runner) all templates rendered
2019/09/04 08:11:16.000191 [DEBUG] (runner) receiving dependency vault.read(secret/foo)
2019/09/04 08:11:16.000204 [DEBUG] (runner) initiating run
2019/09/04 08:11:16.000208 [DEBUG] (runner) checking template 8b68f95ab9f9437dc77a2efb1a5d70a9
2019/09/04 08:11:16.000324 [DEBUG] (runner) rendering "template.txt" => "out.txt"
2019/09/04 08:11:16.000354 [DEBUG] (runner) diffing and updating dependencies
2019/09/04 08:11:16.000358 [DEBUG] (runner) vault.read(secret/foo) is still needed
2019/09/04 08:11:16.000362 [DEBUG] (runner) watching 1 dependencies
2019/09/04 08:11:16.000365 [DEBUG] (runner) all templates rendered
2019/09/04 08:11:17.000291 [DEBUG] (runner) receiving dependency vault.read(secret/foo)
2019/09/04 08:11:17.000301 [DEBUG] (runner) initiating run
2019/09/04 08:11:17.000307 [DEBUG] (runner) checking template 8b68f95ab9f9437dc77a2efb1a5d70a9
2019/09/04 08:11:17.000422 [DEBUG] (runner) rendering "template.txt" => "out.txt"
2019/09/04 08:11:17.000452 [DEBUG] (runner) diffing and updating dependencies
2019/09/04 08:11:17.000456 [DEBUG] (runner) vault.read(secret/foo) is still needed
2019/09/04 08:11:17.000460 [DEBUG] (runner) watching 1 dependencies
2019/09/04 08:11:17.000463 [DEBUG] (runner) all templates rendered
^C2019/09/04 08:11:17.748957 [DEBUG] (cli) receiving signal "interrupt"
Cleaning up...
2019/09/04 08:11:17.748967 [INFO] (runner) stopping
2019/09/04 08:11:17.748970 [DEBUG] (runner) stopping watcher
2019/09/04 08:11:17.748974 [DEBUG] (watcher) stopping all views

If we revert back to 0.21.0:

2019/09/04 08:08:41.885411 [INFO] consul-template v0.21.0 (05c6b650)
2019/09/04 08:08:41.885450 [INFO] (runner) creating new runner (dry: false, once: false)
2019/09/04 08:08:41.886201 [DEBUG] (runner) final config: {"Consul":{"Address":"","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":9,"TLSHandshakeTimeout":10000000000}},"Dedup":{"Enabled":false,"MaxStale":2000000000,"Prefix":"consul-template/dedup/","TTL":15000000000},"Exec":{"Command":"","Enabled":false,"Env":{"Blacklist":[],"Custom":[],"Pristine":false,"Whitelist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":0},"KillSignal":2,"LogLevel":"trace","MaxStale":2000000000,"PidFile":"","ReloadSignal":1,"Syslog":{"Enabled":false,"Facility":"LOCAL0"},"Templates":[{"Backup":false,"Command":"","CommandTimeout":30000000000,"Contents":"","CreateDestDirs":true,"Destination":"out.txt","ErrMissingKey":false,"Exec":{"Command":"","Enabled":false,"Env":{"Blacklist":[],"Custom":[],"Pristine":false,"Whitelist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":30000000000},"Perms":0,"Source":"template.txt","Wait":{"Enabled":false,"Min":0,"Max":0},"LeftDelim":"","RightDelim":"","FunctionBlacklist":null}],"Vault":{"Address":"http://127.0.0.1:8200","Enabled":true,"Grace":15000000000,"Namespace":"","RenewToken":false,"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":9,"TLSHandshakeTimeout":10000000000},"UnwrapToken":false},"Wait":{"Enabled":false,"Min":0,"Max":0},"Once":false}
2019/09/04 08:08:41.886327 [INFO] (runner) creating watcher
2019/09/04 08:08:41.886656 [INFO] (runner) starting
2019/09/04 08:08:41.886705 [DEBUG] (runner) running initial templates
2019/09/04 08:08:41.886736 [DEBUG] (runner) initiating run
2019/09/04 08:08:41.886826 [DEBUG] (runner) checking template 8b68f95ab9f9437dc77a2efb1a5d70a9
2019/09/04 08:08:41.887710 [DEBUG] (runner) was not watching 1 dependencies
2019/09/04 08:08:41.887774 [DEBUG] (watcher) adding vault.read(secret/foo)
2019/09/04 08:08:41.887789 [TRACE] (watcher) vault.read(secret/foo) starting
2019/09/04 08:08:41.887820 [DEBUG] (runner) diffing and updating dependencies
2019/09/04 08:08:41.887841 [DEBUG] (runner) watching 1 dependencies
2019/09/04 08:08:41.887957 [TRACE] (view) vault.read(secret/foo) starting fetch
2019/09/04 08:08:41.891932 [TRACE] vault.read(secret/foo): GET /v1/secret/data/foo
2019/09/04 08:08:41.893380 [TRACE] (view) vault.read(secret/foo) marking successful data response
2019/09/04 08:08:41.893431 [TRACE] (view) vault.read(secret/foo) successful contact, resetting retries
2019/09/04 08:08:41.893448 [TRACE] (view) vault.read(secret/foo) received data
2019/09/04 08:08:41.893505 [TRACE] (view) vault.read(secret/foo) starting fetch
2019/09/04 08:08:41.893519 [DEBUG] (runner) receiving dependency vault.read(secret/foo)
2019/09/04 08:08:41.893535 [TRACE] vault.read(secret/foo): secret is not renewable, sleeping for 4m26.420068403s
2019/09/04 08:08:41.893563 [DEBUG] (runner) initiating run
2019/09/04 08:08:41.893592 [DEBUG] (runner) checking template 8b68f95ab9f9437dc77a2efb1a5d70a9
2019/09/04 08:08:41.894311 [DEBUG] (runner) rendering "template.txt" => "out.txt"
2019/09/04 08:08:41.894458 [DEBUG] (runner) diffing and updating dependencies
2019/09/04 08:08:41.894494 [DEBUG] (runner) vault.read(secret/foo) is still needed
2019/09/04 08:08:41.894517 [DEBUG] (runner) watching 1 dependencies
2019/09/04 08:08:41.894535 [DEBUG] (runner) all templates rendered

Is this to be expected? If so, we would probably have to turn off logging of any log level below info or the log collector will be swamped with these log messages.

[teeuwes]

If it helps, I was seeing identical behavior trying to read in pki info from vault. Based on an old issue, I reverted all the way to 0.19.5, which fixed my issue. I had tried 0.21.2 and 0.20.0, both were broken in the way mentioned above. consul-template kept generating a new pki cert in vault every 5s. 0.19.5 and 0.21.0 seem fine.

[dconry]

fwiw, we were hit by this on upgrade from 0.21.0 to 0.21.2. I'll try to collect more info about our specific environment, if it would be helpful.

[eikenb]

Hey @lawliet89, @teeuwes, @dconry .. My apologies for the issue. Test suite didn't cover the retry timing due to the way delays were implemented and I missed this regression. This has already been filed as #1272 and I have a PR under review right now that fixes the issue. I should be getting 0.21.3 out today with the fix.

[eikenb]

Oh, I wanted to mention that the reworking to fix the bug changed how it worked so it could be tested (and it is in the PR). The PR is #1277.