TTL checks don't fulfill their guarantees when consul is restarted
- Dominant language
- Go
- Stars
- 30.1k
- Forks
- 4.6k
- Avg merge
- 2d 6h
- Merged PRs (30d)
- 43
Description
### `consul version` for both Client and Server
Client: `0.9.3`
Server: `0.9.3`
### `consul info` for both Client and Server
Client:
```
agent:
check_monitors = 0
check_ttls = 0
checks = 0
services = 0
build:
prerelease =
revision =
version = 0.9.3
consul:
known_servers = 3
server = false
runtime:
arch = amd64
cpu_count = 1
goroutines = 40
max_procs = 1
os = linux
version = go1.9
serf_lan:
coordinate_resets = 0
encrypted = false
event_queue = 0
event_time = 12
failed = 0
health_score = 0
intent_queue = 0
left = 0
member_time = 40
members = 5
query_queue = 0
query_time = 1
```
Server:
```
agent:
check_monitors = 0
check_ttls = 1
checks = 1
services = 1
build:
prerelease =
revision =
version = 0.9.3
consul:
bootstrap = false
known_datacenters = 1
leader = true
leader_addr = 10.0.0.1:8300
server = true
raft:
applied_index = 76153
commit_index = 76153
fsm_pending = 0
last_contact = 0
last_log_index = 76153
last_log_term = 65
last_snapshot_index = 74139
last_snapshot_term = 65
latest_configuration = [{Suffrage:Voter ID:10.0.0.2:8300 Address:10.0.0.2:8300} {Suffrage:Voter ID:10.0.0.3:8300 Address:10.0.0.3:8300} {Suffrage:Voter ID:10.0.0.1:8300 Address:10.0.0.1:8300}]
latest_configuration_index = 1
num_peers = 2
protocol_version = 2
protocol_version_max = 3
protocol_version_min = 0
snapshot_version_max = 1
snapshot_version_min = 0
state = Leader
term = 65
runtime:
arch = amd64
cpu_count = 1
goroutines = 95
max_procs = 1
os = linux
version = go1.9
serf_lan:
coordinate_resets = 0
encrypted = false
event_queue = 0
event_time = 12
failed = 0
health_score = 0
intent_queue = 0
left = 0
member_time = 40
members = 5
query_queue = 0
query_time = 1
serf_wan:
coordinate_resets = 0
encrypted = false
event_queue = 0
event_time = 1
failed = 0
health_score = 0
intent_queue = 0
left = 0
member_time = 22
members = 3
query_queue = 0
query_time = 1
```
### Operating system and Environment details
NixOS
### Description of the Issue (and unexpected/desired result)
The [Checks](https://www.consul.io/docs/agent/checks.html) page says about *Time to Live (TTL)* checks:
> TTL checks also persist their last known status to disk. This allows the Consul agent to restore the last known status of the check across restarts.
And importantly
> Persisted check status is valid through the end of the TTL from the time of the last check.
This suggests that
* if a TTL check with TTL = 2s is passing,
* and the consul cluster reboots for 30 seconds,
* then when it comes back up that TTL check should NOT be passing.
And in fact this is the only reasonable way I can imagine this feature to be useful.
**But the check comes back as passing!**
Extract from my `journalctl` logs on a consul server:
```
Oct 11 13:17:00.984571 gluster-cluster-1 glusterVolumeRunningCheckWatchdog-start[866]: Online : Y
Oct 11 13:17:01.027239 gluster-cluster-1 consul[753]: 2017/10/11 13:17:01 [INFO] agent: Synced check 'service:gluster-volume-distfs'
# Reboot is issued
Oct 11 13:17:01.718544 gluster-cluster-1 systemd[1]: Received SIGINT.
Oct 11 13:17:01.797869 gluster-cluster-1 consul[753]: 2017/10/11 13:17:01 [INFO] Caught signal: terminated
Oct 11 13:17:01.797869 gluster-cluster-1 consul[753]: 2017/10/11 13:17:01 [INFO] Graceful shutdown disabled. Exiting
Oct 11 13:17:01.797869 gluster-cluster-1 consul[753]: 2017/10/11 13:17:01 [INFO] agent: Requesting shutdown
Oct 11 13:17:01.797869 gluster-cluster-1 consul[753]: 2017/10/11 13:17:01 [INFO] consul: shutting down server
Oct 11 13:17:01.797869 gluster-cluster-1 consul[753]: 2017/10/11 13:17:01 [WARN] serf: Shutdown without a Leave
Oct 11 13:17:01.797869 gluster-cluster-1 consul[753]: 2017/10/11 13:17:01 [INFO] manager: shutting down
Oct 11 13:17:01.797869 gluster-cluster-1 consul[753]: 2017/10/11 13:17:01 [INFO] raft: aborting pipeline replication to peer {Voter 10.0.0.3:8300 10.0.0.3:8300}
Oct 11 13:17:01.797869 gluster-cluster-1 consul[753]: 2017/10/11 13:17:01 [INFO] raft: aborting pipeline replication to peer {Voter 10.0.0.2:8300 10.0.0.2:8300}
Oct 11 13:17:01.797869 gluster-cluster-1 consul[753]: 2017/10/11 13:17:01 [INFO] agent: consul server down
Oct 11 13:17:01.797869 gluster-cluster-1 consul[753]: 2017/10/11 13:17:01 [INFO] agent: shutdown complete
Oct 11 13:17:01.797869 gluster-cluster-1 consul[753]: 2017/10/11 13:17:01 [INFO] agent: Stopping DNS server 127.0.0.1:8600 (tcp)
Oct 11 13:17:01.797869 gluster-cluster-1 consul[753]: 2017/10/11 13:17:01 [INFO] agent: Stopping DNS server 127.0.0.1:8600 (udp)
Oct 11 13:17:01.797869 gluster-cluster-1 consul[753]: 2017/10/11 13:17:01 [INFO] agent: Stopping HTTP server 127.0.0.1:8500
Oct 11 13:17:01.797869 gluster-cluster-1 consul[753]: 2017/10/11 13:17:01 [INFO] agent: Waiting for endpoints to shut down
Oct 11 13:17:01.797869 gluster-cluster-1 consul[753]: 2017/10/11 13:17:01 [INFO] agent: Endpoints down
Oct 11 13:17:01.797869 gluster-cluster-1 consul[753]: 2017/10/11 13:17:01 [INFO] Exit code: 1
Oct 11 13:17:01.799358 gluster-cluster-1 systemd[1]: Stopping consul.service...
...
Oct 11 13:17:07.127014 gluster-cluster-1 systemd-journald[465]: Journal stopped
-- Reboot --
Oct 11 13:17:36.257998 gluster-cluster-1 kernel: Linux version 4.9.52 (nixbld@localhost) (gcc version 6.4.0 (GCC) ) #1-NixOS SMP Wed Sep 27 12:40:05 UTC 2017
...
# consul boots up successfully
...
Oct 11 13:16:36.148334 gluster-cluster-1 consul[753]: 2017/10/11 13:16:36 [INFO] consul: cluster leadership acquired
...
Oct 11 13:17:39.917474 gluster-cluster-1 consul[754]: 2017/10/11 13:17:39 [WARN] agent: Check 'service:gluster-volume-distfs' missed TTL, is now critical
```
From`journalctl` on a different machine, a consul client, a `/health` check is done to see if the check is passing:
```
Oct 11 13:17:46 gluster-client-1 glusterReadyForClientMount-pre-start[859]: [{'Node': {'ID': '945c37d3-2c94-ed91-2999-3f54b82b30cc', 'Node': 'gluster-cluster-1', 'Address': '10.0.0.1', 'Datacenter': 'dc1', 'TaggedAddresses': {'lan': '10.0.0.1', 'wan': '10.0.0.1'}, 'Meta': {'consul-network-segment': ''}, 'CreateIndex': 57669, 'ModifyIndex': 59501}, 'Service': {'ID': 'gluster-volume-distfs', 'Service': 'gluster-volume-distfs', 'Tags': [], 'Address': '10.0.0.1', 'Port': 0, 'EnableTagOverride': False, 'CreateIndex': 57669, 'ModifyIndex': 57669}, 'Checks': [{'Node': 'gluster-cluster-1', 'CheckID': 'serfHealth', 'Name': 'Serf Health Status', 'Status': 'passing', 'Notes': '', 'Output': 'Agent alive and reachable', 'ServiceID': '', 'ServiceName': '', 'ServiceTags': [], 'CreateIndex': 57669, 'ModifyIndex': 57669}, {'Node': 'gluster-cluster-1', 'CheckID': 'service:gluster-volume-distfs', 'Name': "Service 'gluster-volume-distfs' check", 'Status': 'passing', 'Notes': '', 'Output': 'Command exited with exit code 0 on 2017-10-11 13:17:01.022336:\nset -euo pipefail; /nix/store/0c5ha9n08hw57d612gp7gilg0hh8rqzj-glusterfs-3.10.2/bin/gluster volume status distfs 10.0.0.1:/data/glusterfs/distfs/brick1/brick detail | grep "^Online.*Y"', 'ServiceID': 'gluster-volume-distfs', 'ServiceName': 'gluster-volume-distfs', 'ServiceTags': [], 'CreateIndex': 57669, 'ModifyIndex': 59855}]}]
```
Important in this long output is only the time stamp; not important but also useful is the `Output` field that shows that on the server side the last successful check happened at `13:17:01` which is in line with what the journalctl of the server where that happened say. (Also note I set `check_update_interval = "1ns";` just to make sure that the output is not outdated; but as I said the output is only informational and the bug would still be clear without it.)
---
#### Summary
From the two logs above we can see that for a check with TTL = 2 seconds:
* at `13:17:01` the check was last marked as passing
* then reboot
* at `13:16:36` consul was up and working again
* at `13:17:46` the consul server tells the client that the TTL check is passing
* at `13:17:39` the check was marked as TTL missed
**This means consul answered a TTL check query with "passing" 43 seconds after the TTL expired.**
### Reproduction steps
Create a check with 2 seconds TTL, set up a daemon that starts at boot that marks the check as passing after 60 seconds. Wait for the check to go green. Reboot. Then look at consul's logs.
### Possible solution
It seems that consul should check whether the TTL is expired when answering a query about a TTL check.
Contributor guide
Assessment
This issue has not been assessed yet.