Fabio: Q: Does Fabio handle Consul service health changes well?

[stevehorsfield]

Context

Based on https://github.com/eBay/fabio/blob/128b59ccb543832312ea2050b8154b4fd0ee93b8/registry/consul/service.go#L20-L30.

We see a huge number of log messages such as:

2017/02/03 12:13:53 [INFO] consul: Health changed to #41083871

Expected behaviour:

Log messages only when health state of a service is changed.

Perceived behaviour

Log messages any time the health data is written.

My gut feeling is that Fabio is acting on any change to the Consul health value, not only on a change in state (i.e. critical/warning/healthy). Could you please confirm.

Comment

Could you please confirm if this is expected behaviour? If so, should there be an option to disable the output of these messages? If not, can we get it fixed? We're happy to put a PR together.

[magiconair]

If you see a lot of these messages then you have a flapping service in your setup. This message is printed when the internal state of the consul cluster changes which happens on registration or deregistration of a service or when the health endpoint of a service is flapping. My suggestion is to run consul monitor --log-level=debug and see what is going on.

[magiconair]

Oh, and to answer your question: Yes, fabio acts on any change in the consul state, pulls the full state to build the routing table. The assumption is that your setup is stable once it has converged and that there isn't a lot of change. Hence, if you see a lot of change your setup isn't stable and hasn't converged.

[stevehorsfield]

This sounds wrong to me, but perhaps I am missing something. Why would you consider an index change to be equivalent to a state change?

[magiconair]

Since this is the way the consul and it's blocking API works. consul maintains a replicated state among its master nodes. This state is indexed with a number - the version. Every time I make a query I get the version that result is based on as meta data in the response so that I can use that for subsequent queries, e.g. please notify me if your state changes beyond version X. As long as the state does not change (no service deployment, health change) fabio just performs a blocking wait (long poll) on the consul API. Once the state changes fabio pulls the full state, e.g. all services, all health checks to determine the new routing table. If the routing table did not change then fabio won't do anything to the main proxy thread but it will report that the consul state has changed nevertheless. This is an indication that something is constantly changing in the consul state, e.g. a service which doesn't have a urlprefix- tag.

I may not need to report a change every time I get notified of one but it also provides an indication that there is something else going on in your system. fabio could also identify the delta and log it.

[stevehorsfield]

Understand that, especially the part of how Consul works. However, Consul's design also allows storage of the health check output. I don't really mind that fabio resets the routing table on changes of that kind (although it seems like wasted effort), but the resulting logging is enormous.

I'm trying to establish how Consul handles health checks. We use a variety (scripted, TCP, HTTP) and several of them include substantial data in the response and occur frequently.

[magiconair]

What do you mean by "storage of health check output"? Sure, I can cache the response but that doesn't change the fact that fabio has to pull the new state from consul to determine that there was no change. Try running consul monitor --log-level=debug to find the source of the state changes and your log files will be much smaller. We had the same issue internally where another group was seeing this and asked to remove that log output. I've urged them to find the root cause of the problem and once they did it wasn't a problem anymore.

[stevehorsfield]

To give an example, we have health checks that review DNS connectivity or systemd unit status. For example:

● docker.service - Docker Application Container Engine
   Loaded: loaded (/usr/lib/systemd/system/docker.service; disabled; vendor preset: disabled)
  Drop-In: /etc/systemd/system/docker.service.d
           └─docker-bridge.conf, docker-opts.conf
   Active: active (running) since Fri 2017-01-27 01:44:46 UTC; 1 weeks 0 days ago
     Docs: http://docs.docker.com
 Main PID: 1068 (dockerd)
    Tasks: 11
   Memory: 731.2M
      CPU: 4min 2.334s
   CGroup: /system.slice/docker.service
           └─1068 dockerd --host=fd:// --containerd=/var/run/docker/libcontainerd/docker-containerd.sock --log-level=warn --dns 172.17.42.1 --dns-search=service.consul --bip=<redacted> --selinux-enabled
OK - docker is active.

This data changes on every health check but the status passing remains constant. My guess is this causes a K/V index change every time the health check runs. This particular health check isn't a service health check, so doesn't affect Fabio, but I see three possibilities:

• The Consul health check index changes on every health check execution
• The Consul health check index changes on every health check execution where the output changes
• The Consul health check index only changes when the health status changes

We'll do some investigation to identify which of these cases is the actual behaviour. The second case may require us to change how we respond to health checks. The third is ideal. The first case means we have no control but would also suggest that other users would see high logging levels.

[magiconair]

Number 2: don't include volatile data in the health response (e.g. timestamp). We ran into that as well.

[magiconair]

I've just mentioned this in a PR: We log about 15.000 lines or 1MB per day for 5000 req/sec on production. 90% of the log messages are for routes that don't exist. Once we remove that we should be at 100KB of logs per day.

[stevehorsfield]

We're looking at removing volatile data from the health checks. Thanks for the confirmation.

[magiconair]

I think we can close this one. Please comment if there is something to add and I'll re-open if necessary.