search

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

Newer versions of consul-template are re-running constantly #612

Closed ahelmberger closed 8 years ago

ahelmberger commented 8 years ago

We use consul-template to recreate an nginx config file on each service change. It worked great with version 0.10.0, but we updated to 0.14.0 and get the behavior that consul-template is re-running the template constantly (about every second). Same problem with version 0.12.0. Switching back to version 0.10.0 solves the problem. The template looks like that:

# Available services:
# -----------------------------------------------------------------------------
{{range services}}{{range service .Name}}# {{.Name}} -> {{.Address}}:{{.Port}}
{{end}}{{end}}

{{plugin "un-nginx-reconfig" "--config" "/etc/un-nginx-reconfig.config.json"}}

I attached the logs from v0.14.0 running just a few seconds. Maybe somebody could give us a hint on what's wrong?

Thanks.

consul-template_20160420.log.txt

sethvargo commented 8 years ago

Hi @ahelmberger

Thank you for opening an issue. Could you please share the template you are using as well as the complete output in debug mode? The output you provided does not include the initial debug output (which includes the compiled config and setup steps).

madhurranjan commented 8 years ago

I've the same issue with 0.14.0. my template is 

{{ range $k,$value := tree "applications/app1/regions/us-west-2/ms/" | explode | toJSON | plugin "my-plugin" | parseJSON }}
Rule {{ $k }}
-A POSTROUTING -s {{$value.ConsulIP}}/32 -j SNAT --to-source {{ $value.LocalIP }}
{{ end }}

my-plugin is a custom template.

Output debug log

2016/05/11 06:45:44 [INFO] (runner) running
2016/05/11 06:45:44 [DEBUG] (runner) checking template /opt/test/out
2016/05/11 06:45:44 [DEBUG] ("storeKeyPrefix(applications/app1/regions/us-west-2/ms)") querying consul with &{Datacenter: AllowStale:true RequireConsistent:false WaitIndex:329251 WaitTime:1m0s Token: Near:}
2016/05/11 06:45:44 [INFO] (runner) diffing and updating dependencies
2016/05/11 06:45:44 [DEBUG] (runner) "storeKeyPrefix(applications/app1/regions/us-west-2/ms)" is still needed
2016/05/11 06:45:44 [INFO] (runner) watching 1 dependencies
2016/05/11 06:45:45 [DEBUG] ("storeKeyPrefix(applications/app1/regions/us-west-2/ms)") Consul returned 14 key pairs
2016/05/11 06:45:45 [INFO] (view) "storeKeyPrefix(applications/app1/regions/us-west-2/ms)" received data
2016/05/11 06:45:45 [DEBUG] (view) "storeKeyPrefix(applications/app1/regions/us-west-2/ms)" starting fetch
2016/05/11 06:45:45 [DEBUG] ("storeKeyPrefix(applications/app1/regions/us-west-2/ms)") querying consul with &{Datacenter: AllowStale:true RequireConsistent:false WaitIndex:329252 WaitTime:1m0s Token: Near:}
2016/05/11 06:45:45 [DEBUG] (runner) receiving dependency "storeKeyPrefix(applications/app1/regions/us-west-2/ms)"
2016/05/11 06:45:45 [INFO] (runner) running
2016/05/11 06:45:45 [DEBUG] (runner) checking template /opt/test/out
2016/05/11 06:45:45 [INFO] (runner) diffing and updating dependencies
2016/05/11 06:45:45 [DEBUG] (runner) "storeKeyPrefix(applications/app1/regions/us-west-2/ms)" is still needed
2016/05/11 06:45:45 [INFO] (runner) watching 1 dependencies
2016/05/11 06:45:47 [DEBUG] ("storeKeyPrefix(applications/app1/regions/us-west-2/ms)") Consul returned 14 key pairs
2016/05/11 06:45:47 [INFO] (view) "storeKeyPrefix(applications/app1/regions/us-west-2/ms)" received data
2016/05/11 06:45:47 [DEBUG] (view) "storeKeyPrefix(applications/app1/regions/us-west-2/ms)" starting fetch
2016/05/11 06:45:47 [DEBUG] ("storeKeyPrefix(applications/app1/regions/us-west-2/ms)") querying consul with &{Datacenter: AllowStale:true RequireConsistent:false WaitIndex:329255 WaitTime:1m0s Token: Near:}
2016/05/11 06:45:47 [DEBUG] (runner) receiving dependency "storeKeyPrefix(applications/app1/regions/us-west-2/ms)"
2016/05/11 06:45:47 [INFO] (runner) running
2016/05/11 06:45:47 [DEBUG] (runner) checking template /opt/test/out
2016/05/11 06:45:47 [INFO] (runner) diffing and updating dependencies
2016/05/11 06:45:47 [DEBUG] (runner) "storeKeyPrefix(applications/app1/regions/us-west-2/ms)" is still needed
2016/05/11 06:45:47 [INFO] (runner) watching 1 dependencies
2016/05/11 06:45:51 [DEBUG] ("storeKeyPrefix(applications/app1/regions/us-west-2/ms)") Consul returned 14 key pairs
2016/05/11 06:45:51 [INFO] (view) "storeKeyPrefix(applications/app1/regions/us-west-2/ms)" received data
2016/05/11 06:45:51 [DEBUG] (view) "storeKeyPrefix(applications/app1/regions/us-west-2/ms)" starting fetch
2016/05/11 06:45:51 [DEBUG] ("storeKeyPrefix(applications/app1/regions/us-west-2/ms)") querying consul with &{Datacenter: AllowStale:true RequireConsistent:false WaitIndex:329258 WaitTime:1m0s Token: Near:}
2016/05/11 06:45:51 [DEBUG] (runner) receiving dependency "storeKeyPrefix(applications/app1/regions/us-west-2/ms)"
2016/05/11 06:45:51 [INFO] (runner) running
2016/05/11 06:45:51 [DEBUG] (runner) checking template /opt/test/out
2016/05/11 06:45:51 [INFO] (runner) diffing and updating dependencies
2016/05/11 06:45:51 [DEBUG] (runner) "storeKeyPrefix(applications/app1/regions/us-west-2/ms)" is still needed
2016/05/11 06:45:51 [INFO] (runner) watching 1 dependencies
2016/05/11 06:45:54 [INFO] (runner) quiescence minTimer fired for /opt/test/out
2016/05/11 06:45:54 [INFO] (runner) received template "/opt/test/out" from quiescence
2016/05/11 06:45:54 [INFO] (runner) running
2016/05/11 06:45:54 [DEBUG] (runner) checking template /opt/test/out
2016/05/11 06:45:54 [DEBUG] (runner) checking ctemplate &{Source:/opt/test/out Destination:/tmp/result Command:iptables-restore -c < /tmp/result CommandTimeout:30s Perms:-rw-r--r-- Backup:false}
2016/05/11 06:45:54 [DEBUG] (runner) wouldRender: true, didRender: false
2016/05/11 06:45:54 [INFO] (runner) diffing and updating dependencies
2016/05/11 06:45:54 [DEBUG] (runner) "storeKeyPrefix(applications/app1/regions/us-west-2/ms)" is still needed
2016/05/11 06:45:54 [DEBUG] (runner) enabling quiescence for "/opt/test/out"
2016/05/11 06:45:54 [INFO] (runner) watching 1 dependencies
2016/05/11 06:45:55 [DEBUG] ("storeKeyPrefix(applications/app1/regions/us-west-2/ms)") Consul returned 14 key pairs
2016/05/11 06:45:55 [INFO] (view) "storeKeyPrefix(applications/app1/regions/us-west-2/ms)" received data
2016/05/11 06:45:55 [DEBUG] (view) "storeKeyPrefix(applications/app1/regions/us-west-2/ms)" starting fetch
2016/05/11 06:45:55 [DEBUG] ("storeKeyPrefix(applications/app1/regions/us-west-2/ms)") querying consul with &{Datacenter: AllowStale:true RequireConsistent:false WaitIndex:329259 WaitTime:1m0s Token: Near:}
2016/05/11 06:45:55 [DEBUG] (runner) receiving dependency "storeKeyPrefix(applications/app1/regions/us-west-2/ms)"
2016/05/11 06:45:55 [INFO] (runner) running
2016/05/11 06:45:55 [DEBUG] (runner) checking template /opt/test/out
2016/05/11 06:45:55 [INFO] (runner) diffing and updating dependencies
2016/05/11 06:45:55 [DEBUG] (runner) "stor
sethvargo commented 8 years ago

Hi @ahelmberger

Can you please share the complete debug output? The first few lines should show the JSON-generated configuration, but it looks like this is a mid-log. This might be a duplicate of #608

dverbeek84 commented 8 years ago

I got the same issue with version 0.14.0. In debug mode i don't see 'JSON-generated'

jippi commented 8 years ago

I've seen this kind of constant reloading as well, for me, removing anything to do with timestamp helped

maybe all of it is symptoms on something weird going on? :)

dverbeek84 commented 8 years ago

Sorry, my problem was 8301 port related. You can ignore my comment.

sethvargo commented 8 years ago

Hi all,

I just released 0.15.0. Could you please give it a try and see if the issue is still occurring? If so, can you post the debug output as a Gist? Thanks!

sethvargo commented 8 years ago

Hey there,

I am going to close this due to lack of response, but I'm fairly convinced this has been fixed upstream. If not, please submit a new issue and follow the issue template that pops up. Thanks! 😄

ahelmberger commented 8 years ago

I'm sorry for not getting back at you. We didn't find the time to setup a test environment. But we'll try the new version hopefully soon. Thanks.

kshep commented 8 years ago

We were seeing behavior like this with 0.15.0 that appears to be caused by (1) not configuring wait and (2) trying to include a timestamp in our files.

After we found the wait setting in the docs and updated our consul-template.cfg file

  // This is the `minimum(:maximum)` to wait before rendering a new template to
  // disk and triggering a command, separated by a colon (`:`). If the optional
  // maximum value is omitted, it is assumed to be 4x the required minimum value.
  // This is a numeric time with a unit suffix ("5s"). There is no default value.
  // The wait value for a template takes precedence over any globally-configured
  // wait.
  wait = "30s"

we were still seeing frequent rewrites where nothing in the file was actually changing... except the timestamp. Every template had

#  Last updated: {{ timestamp "2006-01-02 15:04:05 MST"}}

so it was easy to see when, y'know, the file was last updated. After removing that, 90%+ of our consult-template log entries that used to be

[DEBUG] (runner) wouldRender: true, didRender: true

are now

[DEBUG] (runner) wouldRender: true, didRender: false

and we're no longer constantly running the post-regen commands (i.e. not constantly bouncing haproxy)

kshep commented 8 years ago

I'll bet this is related to https://github.com/hashicorp/consul-template/issues/561