Renewing a vault token defaults to true even when no vault tokens are in use... should default to false in this case.

[ChipV223]

Consul Template version

v0.22.0

Configuration

log_level = "debug"

consul {

	address = "127.0.0.1:8501"
	
	retry {
    # This enabled retries. Retries are enabled by default, so this is
    # redundant.
    enabled = true

    # This specifies the number of attempts to make before giving up. Each
    # attempt adds the exponential backoff sleep time. Setting this to
    # zero will implement an unlimited number of retries.
    attempts = 10

    # This is the base amount of time to sleep between retry attempts. Each
    # retry sleeps for an exponent of 2 longer than this base. For 5 retries,
    # the sleep times would be: 250ms, 500ms, 1s, 2s, then 4s.
    backoff = "250ms"

    # This is the maximum amount of time to sleep between retry attempts.
    # When max_backoff is set to zero, there is no upper limit to the
    # exponential sleep between retry attempts.
    # If max_backoff is set to 10s and backoff is set to 1s, sleep times
    # would be: 1s, 2s, 4s, 8s, 10s, 10s, ...
    max_backoff = "1m"
	}
	
	# This block configures the SSL options for connecting to the Consul server.
	ssl {
    # This enables SSL. Specifying any option for SSL will also enable it.
    enabled = true

    # This enables SSL peer verification. The default value is "true", which
    # will check the global CA chain to make sure the given certificates are
    # valid. If you are using a self-signed certificate that you have not added
    # to the CA chain, you may want to disable SSL verification. However, please
    # understand this is a potential security vulnerability.
    verify = true

    # This is the path to the certificate to use to authenticate. If just a
    # certificate is provided, it is assumed to contain both the certificate and
    # the key to convert to an X509 certificate. If both the certificate and
    # key are specified, Consul Template will automatically combine them into an
    # X509 certificate for you.
    cert = "C:\\Consul_Service2\\certs\\server\\dc1-server-consul-0.pem"
    key  = "C:\\Consul_Service2\\certs\\server\\dc1-server-consul-0-key.pem"

    # This is the path to the certificate authority to use as a CA. This is
    # useful for self-signed certificates or for organizations using their own
    # internal certificate authority.
    ca_cert = "C:\\Consul_Service2\\certs\\consul-agent-ca.pem"

  }
}

template {
  source = "C:\\Consul_Service2\\template\\all_services.tpl"
  destination = "C:\\Consul_Service2\\template\\output_1.txt"
  create_dest_dirs = true
  error_on_missing_key = true

  wait {
      min = "2s"
      max = "10s"
  }
}


template {
  source = "C:\\Consul_Service2\\template\\find_key.tpl"
  destination = "C:\\Consul_Service2\\template\\output_2.txt"
  create_dest_dirs = true
  error_on_missing_key = true

  wait {
      min = "2s"
      max = "10s"
  }
}

Command

consul-template -config=config.hcl

Debug output

chipv@CV-HASHI C:\Consul_Service2\template
$ consul-template -config=config.hcl
2019/10/29 18:36:16.684529 [INFO] consul-template v0.22.0 (6cae10fe)
2019/10/29 18:36:16.685526 [INFO] (runner) creating new runner (dry: false, once: false)
2019/10/29 18:36:16.686523 [DEBUG] (runner) final config: {"Consul":{"Address":"127.0.0.1:8501","Auth":{"Enabled":false,"Username":"","Password":""},"Retry":{"Attempts":10,"Backoff":250000000,"MaxBackoff":60000000000,"Enabled":true},"SSL":{"CaCert":"C:\\Consul_Service2\\certs\\consul-agent-ca.pem","CaPath":"","Cert":"C:\\Consul_Service2\\certs\\server\\dc1-server-consul-0.pem","Enabled":true,"Key":"C:\\Consul_Service2\\certs\\server\\dc1-server-consul-0-key.pem","ServerName":"","Verify":true},"Token":"","Transport":{"DialKeepAlive":30000000000,"DialTimeout":30000000000,"DisableKeepAlives":false,"IdleConnTimeout":90000000000,"MaxIdleConns":100,"MaxIdleConnsPerHost":5,"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":"C:\\Consul_Service2\\template\\output_1.txt","ErrMissingKey":true,"Exec":{"Command":"","Enabled":false,"Env":{"Blacklist":[],"Custom":[],"Pristine":false,"Whitelist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":30000000000},"Perms":0,"Source":"C:\\Consul_Service2\\template\\all_services.tpl","Wait":{"Enabled":true,"Min":2000000000,"Max":10000000000},"LeftDelim":"","RightDelim":"","FunctionBlacklist":null,"SandboxPath":""},{"Backup":false,"Command":"","CommandTimeout":30000000000,"Contents":"","CreateDestDirs":true,"Destination":"C:\\Consul_Service2\\template\\output_2.txt","ErrMissingKey":true,"Exec":{"Command":"","Enabled":false,"Env":{"Blacklist":[],"Custom":[],"Pristine":false,"Whitelist":[]},"KillSignal":2,"KillTimeout":30000000000,"ReloadSignal":null,"Splay":0,"Timeout":30000000000},"Perms":0,"Source":"C:\\Consul_Service2\\template\\find_key.tpl","Wait":{"Enabled":true,"Min":2000000000,"Max":10000000000},"LeftDelim":"","RightDelim":"","FunctionBlacklist":null,"SandboxPath":""}],"Vault":{"Address":"","Enabled":false,"Grace":15000000000,"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":5,"TLSHandshakeTimeout":10000000000},"UnwrapToken":false},"Wait":{"Enabled":false,"Min":0,"Max":0},"Once":false}
2019/10/29 18:36:16.706470 [INFO] (runner) creating watcher
2019/10/29 18:36:16.706470 [DEBUG] (watcher) adding vault.token
2019/10/29 18:36:16.707468 [INFO] (runner) starting
2019/10/29 18:36:16.707468 [DEBUG] (runner) running initial templates
2019/10/29 18:36:16.707468 [DEBUG] (runner) initiating run
2019/10/29 18:36:16.707468 [DEBUG] (runner) checking template 0f9e4eaf1157802a560f21e36c232be3
2019/10/29 18:36:16.708465 [DEBUG] (runner) was not watching 1 dependencies
2019/10/29 18:36:16.708465 [DEBUG] (watcher) adding catalog.services
2019/10/29 18:36:16.709462 [DEBUG] (runner) checking template 16585f422f761b01857cd1dc297323b9
2019/10/29 18:36:16.709462 [DEBUG] (runner) was not watching 1 dependencies
2019/10/29 18:36:16.709462 [DEBUG] (watcher) adding kv.get(foo)
2019/10/29 18:36:16.709462 [DEBUG] (runner) diffing and updating dependencies
2019/10/29 18:36:16.710459 [DEBUG] (runner) watching 3 dependencies
2019/10/29 18:36:16.821009 [DEBUG] (runner) receiving dependency kv.get(foo)
2019/10/29 18:36:16.821009 [DEBUG] (runner) initiating run
2019/10/29 18:36:16.821009 [DEBUG] (runner) checking template 0f9e4eaf1157802a560f21e36c232be3
2019/10/29 18:36:16.821009 [DEBUG] (runner) missing data for 1 dependencies
2019/10/29 18:36:16.821009 [DEBUG] (runner) checking template 16585f422f761b01857cd1dc297323b9
2019/10/29 18:36:16.822007 [DEBUG] (runner) rendering "C:\\Consul_Service2\\template\\find_key.tpl" => "C:\\Consul_Service2\\template\\output_2.txt"
2019/10/29 18:36:16.826997 [INFO] (runner) rendered "C:\\Consul_Service2\\template\\find_key.tpl" => "C:\\Consul_Service2\\template\\output_2.txt"
2019/10/29 18:36:16.827992 [DEBUG] (runner) diffing and updating dependencies
2019/10/29 18:36:16.827992 [DEBUG] (runner) catalog.services is still needed
2019/10/29 18:36:16.827992 [DEBUG] (runner) kv.get(foo) is still needed
2019/10/29 18:36:16.827992 [DEBUG] (runner) watching 3 dependencies
2019/10/29 18:36:16.829190 [DEBUG] (runner) receiving dependency catalog.services
2019/10/29 18:36:16.829190 [DEBUG] (runner) initiating run
2019/10/29 18:36:16.829987 [DEBUG] (runner) checking template 0f9e4eaf1157802a560f21e36c232be3
2019/10/29 18:36:16.830985 [DEBUG] (runner) was not watching 3 dependencies
2019/10/29 18:36:16.831982 [DEBUG] (watcher) adding health.service(SimpleHTTPServer|passing)
2019/10/29 18:36:16.831982 [DEBUG] (watcher) adding health.service(consul|passing)
2019/10/29 18:36:16.831982 [DEBUG] (watcher) adding health.service(nginx|passing)
2019/10/29 18:36:16.831982 [DEBUG] (runner) checking template 16585f422f761b01857cd1dc297323b9
2019/10/29 18:36:16.832978 [DEBUG] (runner) rendering "C:\\Consul_Service2\\template\\find_key.tpl" => "C:\\Consul_Service2\\template\\output_2.txt"
2019/10/29 18:36:16.834973 [DEBUG] (runner) diffing and updating dependencies
2019/10/29 18:36:16.835970 [DEBUG] (runner) catalog.services is still needed
2019/10/29 18:36:16.835970 [DEBUG] (runner) kv.get(foo) is still needed
2019/10/29 18:36:16.836968 [DEBUG] (runner) watching 6 dependencies
2019/10/29 18:36:16.938135 [DEBUG] (runner) receiving dependency health.service(consul|passing)
2019/10/29 18:36:16.940131 [DEBUG] (runner) initiating run
2019/10/29 18:36:16.940131 [DEBUG] (runner) checking template 0f9e4eaf1157802a560f21e36c232be3
2019/10/29 18:36:16.941127 [DEBUG] (runner) missing data for 2 dependencies
2019/10/29 18:36:16.942124 [DEBUG] (runner) checking template 16585f422f761b01857cd1dc297323b9
2019/10/29 18:36:16.943121 [DEBUG] (runner) rendering "C:\\Consul_Service2\\template\\find_key.tpl" => "C:\\Consul_Service2\\template\\output_2.txt"
2019/10/29 18:36:16.946113 [DEBUG] (runner) diffing and updating dependencies
2019/10/29 18:36:16.946113 [DEBUG] (runner) catalog.services is still needed
2019/10/29 18:36:16.947110 [DEBUG] (runner) health.service(SimpleHTTPServer|passing) is still needed
2019/10/29 18:36:16.947110 [DEBUG] (runner) health.service(consul|passing) is still needed
2019/10/29 18:36:16.948107 [DEBUG] (runner) health.service(nginx|passing) is still needed
2019/10/29 18:36:16.948107 [DEBUG] (runner) kv.get(foo) is still needed
2019/10/29 18:36:16.949105 [DEBUG] (runner) watching 6 dependencies
2019/10/29 18:36:16.949105 [DEBUG] (runner) receiving dependency health.service(SimpleHTTPServer|passing)
2019/10/29 18:36:16.950102 [DEBUG] (runner) initiating run
2019/10/29 18:36:16.950102 [DEBUG] (runner) checking template 0f9e4eaf1157802a560f21e36c232be3
2019/10/29 18:36:16.951099 [DEBUG] (runner) missing data for 1 dependencies
2019/10/29 18:36:16.951099 [DEBUG] (runner) checking template 16585f422f761b01857cd1dc297323b9
2019/10/29 18:36:16.952097 [DEBUG] (runner) rendering "C:\\Consul_Service2\\template\\find_key.tpl" => "C:\\Consul_Service2\\template\\output_2.txt"
2019/10/29 18:36:16.953094 [DEBUG] (runner) diffing and updating dependencies
2019/10/29 18:36:16.953094 [DEBUG] (runner) health.service(consul|passing) is still needed
2019/10/29 18:36:16.954092 [DEBUG] (runner) health.service(nginx|passing) is still needed
2019/10/29 18:36:16.955090 [DEBUG] (runner) kv.get(foo) is still needed
2019/10/29 18:36:16.955090 [DEBUG] (runner) catalog.services is still needed
2019/10/29 18:36:16.956087 [DEBUG] (runner) health.service(SimpleHTTPServer|passing) is still needed
2019/10/29 18:36:16.957084 [DEBUG] (runner) watching 6 dependencies
2019/10/29 18:36:16.957084 [DEBUG] (runner) receiving dependency health.service(nginx|passing)
2019/10/29 18:36:16.957084 [DEBUG] (runner) initiating run
2019/10/29 18:36:16.957084 [DEBUG] (runner) checking template 0f9e4eaf1157802a560f21e36c232be3
2019/10/29 18:36:16.958081 [DEBUG] (runner) rendering "C:\\Consul_Service2\\template\\all_services.tpl" => "C:\\Consul_Service2\\template\\output_1.txt"
2019/10/29 18:36:16.963068 [INFO] (runner) rendered "C:\\Consul_Service2\\template\\all_services.tpl" => "C:\\Consul_Service2\\template\\output_1.txt"
2019/10/29 18:36:16.964065 [DEBUG] (runner) checking template 16585f422f761b01857cd1dc297323b9
2019/10/29 18:36:16.964065 [DEBUG] (runner) rendering "C:\\Consul_Service2\\template\\find_key.tpl" => "C:\\Consul_Service2\\template\\output_2.txt"
2019/10/29 18:36:16.965063 [DEBUG] (runner) diffing and updating dependencies
2019/10/29 18:36:16.965063 [DEBUG] (runner) health.service(nginx|passing) is still needed
2019/10/29 18:36:16.965063 [DEBUG] (runner) kv.get(foo) is still needed
2019/10/29 18:36:16.965063 [DEBUG] (runner) catalog.services is still needed
2019/10/29 18:36:16.966060 [DEBUG] (runner) health.service(SimpleHTTPServer|passing) is still needed
2019/10/29 18:36:16.966060 [DEBUG] (runner) health.service(consul|passing) is still needed
2019/10/29 18:36:16.966060 [DEBUG] (runner) watching 6 dependencies
2019/10/29 18:36:16.967057 [DEBUG] (runner) all templates rendered
2019/10/29 18:36:16.967057 [DEBUG] (runner) enabling template-specific quiescence for "0f9e4eaf1157802a560f21e36c232be3"
2019/10/29 18:36:16.967057 [DEBUG] (runner) enabling template-specific quiescence for "16585f422f761b01857cd1dc297323b9"
2019/10/29 18:36:26.527875 [WARN] vault.token: failed to renew: Put https://127.0.0.1:8200/v1/auth/token/renew-self: dial tcp 127.0.0.1:8200: connectex: No connection could be made because the target machine actively refused it.
2019/10/29 18:36:26.528872 [WARN] vault.token: renewer done (maybe the lease expired)
2019/10/29 18:36:41.529230 [WARN] (view) lease expired or is not renewable (retry attempt 1 after "250ms")
2019/10/29 18:36:51.188645 [WARN] vault.token: failed to renew: Put https://127.0.0.1:8200/v1/auth/token/renew-self: dial tcp 127.0.0.1:8200: connectex: No connection could be made because the target machine actively refused it.
2019/10/29 18:36:51.188645 [WARN] vault.token: renewer done (maybe the lease expired)
2019/10/29 18:37:06.189272 [WARN] (view) lease expired or is not renewable (retry attempt 2 after "500ms")
2019/10/29 18:37:16.391138 [WARN] vault.token: failed to renew: Put https://127.0.0.1:8200/v1/auth/token/renew-self: dial tcp 127.0.0.1:8200: connectex: No connection could be made because the target machine actively refused it.
2019/10/29 18:37:16.391138 [WARN] vault.token: renewer done (maybe the lease expired)
2019/10/29 18:37:31.391514 [WARN] (view) lease expired or is not renewable (retry attempt 3 after "1s")
2019/10/29 18:37:42.078425 [WARN] vault.token: failed to renew: Put https://127.0.0.1:8200/v1/auth/token/renew-self: dial tcp 127.0.0.1:8200: connectex: No connection could be made because the target machine actively refused it.
2019/10/29 18:37:42.078425 [WARN] vault.token: renewer done (maybe the lease expired)
2019/10/29 18:37:57.079695 [WARN] (view) lease expired or is not renewable (retry attempt 4 after "2s")
2019/10/29 18:38:08.711913 [WARN] vault.token: failed to renew: Put https://127.0.0.1:8200/v1/auth/token/renew-self: dial tcp 127.0.0.1:8200: connectex: No connection could be made because the target machine actively refused it.
2019/10/29 18:38:08.712649 [WARN] vault.token: renewer done (maybe the lease expired)
2019/10/29 18:38:23.712987 [WARN] (view) lease expired or is not renewable (retry attempt 5 after "4s")
2019/10/29 18:38:37.035066 [WARN] vault.token: failed to renew: Put https://127.0.0.1:8200/v1/auth/token/renew-self: dial tcp 127.0.0.1:8200: connectex: No connection could be made because the target machine actively refused it.
2019/10/29 18:38:37.035066 [WARN] vault.token: renewer done (maybe the lease expired)
2019/10/29 18:38:52.035437 [WARN] (view) lease expired or is not renewable (retry attempt 6 after "8s")
2019/10/29 18:39:09.340111 [WARN] vault.token: failed to renew: Put https://127.0.0.1:8200/v1/auth/token/renew-self: dial tcp 127.0.0.1:8200: connectex: No connection could be made because the target machine actively refused it.
2019/10/29 18:39:09.340111 [WARN] vault.token: renewer done (maybe the lease expired)
2019/10/29 18:39:24.341634 [WARN] (view) lease expired or is not renewable (retry attempt 7 after "16s")
2019/10/29 18:39:50.400452 [WARN] vault.token: failed to renew: Put https://127.0.0.1:8200/v1/auth/token/renew-self: dial tcp 127.0.0.1:8200: connectex: No connection could be made because the target machine actively refused it.
2019/10/29 18:39:50.401456 [WARN] vault.token: renewer done (maybe the lease expired)
2019/10/29 18:40:05.401719 [WARN] (view) lease expired or is not renewable (retry attempt 8 after "32s")
2019/10/29 18:40:47.372050 [WARN] vault.token: failed to renew: Put https://127.0.0.1:8200/v1/auth/token/renew-self: dial tcp 127.0.0.1:8200: connectex: No connection could be made because the target machine actively refused it.
2019/10/29 18:40:47.372050 [WARN] vault.token: renewer done (maybe the lease expired)
2019/10/29 18:41:02.372415 [WARN] (view) lease expired or is not renewable (retry attempt 9 after "1m0s")
2019/10/29 18:42:12.427372 [WARN] vault.token: failed to renew: Put https://127.0.0.1:8200/v1/auth/token/renew-self: dial tcp 127.0.0.1:8200: connectex: No connection could be made because the target machine actively refused it.
2019/10/29 18:42:12.427372 [WARN] vault.token: renewer done (maybe the lease expired)
2019/10/29 18:42:27.428474 [WARN] (view) lease expired or is not renewable (retry attempt 10 after "1m0s")
2019/10/29 18:43:36.976102 [WARN] vault.token: failed to renew: Put https://127.0.0.1:8200/v1/auth/token/renew-self: dial tcp 127.0.0.1:8200: connectex: No connection could be made because the target machine actively refused it.
2019/10/29 18:43:36.976865 [WARN] vault.token: renewer done (maybe the lease expired)
2019/10/29 18:43:51.977272 [WARN] (view) lease expired or is not renewable (retry attempt 11 after "1m0s")
2019/10/29 18:45:01.116279 [WARN] vault.token: failed to renew: Put https://127.0.0.1:8200/v1/auth/token/renew-self: dial tcp 127.0.0.1:8200: connectex: No connection could be made because the target machine actively refused it.
2019/10/29 18:45:01.116279 [WARN] vault.token: renewer done (maybe the lease expired)
2019/10/29 18:45:16.116741 [WARN] (view) lease expired or is not renewable (retry attempt 12 after "1m0s")
2019/10/29 18:46:25.602498 [WARN] vault.token: failed to renew: Put https://127.0.0.1:8200/v1/auth/token/renew-self: dial tcp 127.0.0.1:8200: connectex: No connection could be made because the target machine actively refused it.
2019/10/29 18:46:25.602498 [WARN] vault.token: renewer done (maybe the lease expired)
2019/10/29 18:46:40.604034 [ERR] (view) lease expired or is not renewable (exceeded maximum retries)
2019/10/29 18:46:40.604034 [ERR] (runner) watcher reported error: lease expired or is not renewable
2019/10/29 18:46:40.604034 [ERR] (cli) lease expired or is not renewable

Expected behavior

What should have happened?

If Consul Template doesn't detect any Vault parameters in the template config file, the Vault token renew check should be happen once. After it is found that there is no Vault token, the check stops and Consul Template should continue to run

Actual behavior

What actually happened?

Consul Template will continuously try to find a Vault token, resulting in unnecessary logging as well as the process shutting down after the maximum Vault token renew tries have been exceeded

[eikenb]

@ChipV223 I think you might have a token set in a less obvious place as I can't reproduce this if I don't have the token set anywhere.

It can be set in any of the following...

1. token in config file
2. VAULT_TOKEN environment variable
3. ~/.vault-token file (default for the vault_agent_token_file config setting)

If there is no token in any of these places, you shouldn't see those token-refreshing errors.

[ChipV223]

@eikenb : The config I posted earlier shows no token in the config, I don't have VAULT_TOKEN set in my env nor do I was able to find ~/.vault-token in my Windows env

I'll try running C.T. on a different env to see if I'm able to replicate this

[eikenb]

I looked over the code again and it comes down to this line...

consul-template/manager/runner.go

Line 1299 in 9245e2c

RenewVault: clients.Vault().Token() != "" && config.BoolVal(c.Vault.RenewToken),

That line has 2 parts that both must be true for it to try to renew the token. Starting with the second, the config setting config.Bool(c.Vault.RenewToken) defaults to true. So it is likely true in your tests.

The first check clients.Vault().Token() != "" is the problem. To run through it... clients.Vault() returns the vault API client. Running Token() on it just returns its internal client.token value. That only gets set if you set it with client.SetToken() or if the environment variable VAULT_TOKEN is set. Consul-template only calls SetToken if the configuration system finds a token which must come from one of those 3 places I mentioned.

[eikenb]

Hey @ChipV223. If you have anything else that might let me reproduce this, please let me know. Otherwise I'd like to close this ticket.

[eikenb]

the config setting config.Bool(c.Vault.RenewToken) defaults to true.

This just bit me. It shouldn't default to true if Vault isn't used. I'm re-opening this ticket and changing it to changing the default to false when no vault tokens are in use.

[eikenb]

@ChipV223 Note that your original ticket did say this when reading it in hindsight. I just had a certain interpretation in my head based on my knowledge of things at the time and got stuck there. The problem is with the default setting when vault is not in use (as I mentioned)... which should be fixable.