hashicorp / hashicorp/consul

Server temporarily stops responding - Stopping a blocking query leaves goroutines running and in-use file descriptors in the server

Open
#9,647 3 comments 0 reactions 0 assignees View on GitHub
theme/reliability
Dominant language
Go
Stars
30.1k
Forks
4.6k
Avg merge
2d 6h
Merged PRs (30d)
43

Description

#### Overview of the Issue

Stopping a blocking query against the KV store leaves goroutines running in the server that only get reaped after a timeout.
This means a misbehaving client - one that repeatedly terminates after watching for changes in the KV store - causes the number of goroutines on the server to climb rapidly.
After a few minutes, the server will stop responding to some queries and only recover when the number of goroutines decreases.

It looks like the request context isn't used - so resources for a disappearing client connection are left dangling

#### Reproduction Steps
1. start a local consul single-instance server
2. monitor goroutine and file-descriptor counts: `watch "curl -s 'localhost:8500/v1/agent/metrics?format=prometheus' | egrep '^go_gorout|^process_open_fds'"`
3. monitor netstat: `watch -n 1 "sudo netstat -np | grep :8500 | tr -s ' ' | cut -d ' ' -f6 | sort | uniq -c"`
3. generate some blocking get requests: `while true; do timeout -s 15 0.5 curl "http://127.0.0.1:8500/v1/kv/?recurse=false&index=32768"; done`
4. note the number of goroutines and open fds increase along with each blocking request.
5. wait until the server stops responding - the watch on number of goroutines starts to fail (in my case after only a minute at around 490 reported goroutines)
5. stop generating blocking requests.
6. note the net stats fall to almost nothing but the server still doesn't respond - goroutine monitor requests still fail
7. wait about 2.5 minutes to see the server start to respond again to the goroutine monitor
6. watch the number of goroutines and fds slowly fall back to nominal

### Consul info for both Client and Server

Client info

```
consul client not used
```

Server info

```
agent:
check_monitors = 0
check_ttls = 0
checks = 1
services = 6
build:
prerelease =
revision = 1a7f21a0
version = 1.8.8
consul:
acl = disabled
bootstrap = true
known_datacenters = 1
leader = true
leader_addr = 192.168.2.3:8300
server = true
raft:
applied_index = 5387
commit_index = 5387
fsm_pending = 0
last_contact = 0
last_log_index = 5387
last_log_term = 7
last_snapshot_index = 0
last_snapshot_term = 0
latest_configuration = [{Suffrage:Voter ID:be20a374-1ee2-18be-9eed-7ef25820b975 Address:192.168.2.3:8300}]
latest_configuration_index = 0
num_peers = 0
protocol_version = 3
protocol_version_max = 3
protocol_version_min = 0
snapshot_version_max = 1
snapshot_version_min = 0
state = Leader
term = 7
runtime:
arch = amd64
cpu_count = 16
goroutines = 112
max_procs = 16
os = linux
version = go1.14.14
serf_lan:
coordinate_resets = 0
encrypted = false
event_queue = 1
event_time = 2
failed = 0
health_score = 0
intent_queue = 0
left = 0
member_time = 1
members = 1
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 = 1
members = 1
query_queue = 0
query_time = 1
```

### Operating system and Environment details

Ubuntu 20.04

### Log Fragments
no client log - client not used

server log at trace level only contains lines for the curl request that's monitoring the number of goroutines:
`2021-01-27T10:49:36.825Z [DEBUG] agent.http: Request finished: method=GET url=/v1/agent/metrics?format=prometheus from=127.0.0.1:50348 latency=2.44387ms`
`2021-01-27T10:49:37.856Z [DEBUG] agent.http: Request finished: method=GET url=/v1/agent/metrics?format=prometheus from=127.0.0.1:50352 latency=2.512465ms`
`2021-01-27T10:49:38.868Z [DEBUG] agent.http: Request finished: method=GET url=/v1/agent/metrics?format=prometheus from=127.0.0.1:50364 latency=474.669µs`
`2021-01-27T10:49:39.874Z [DEBUG] agent.http: Request finished: method=GET url=/v1/agent/metrics?format=prometheus from=127.0.0.1:50370 latency=474.717µs
`

once the server stops responding to the goroutine monitor requests, there appears to be some normal activity:
` 2021-01-27T11:26:52.884Z [DEBUG] agent: Service in sync: service=ash:portainer.1.t2zf6h6eacl2rz0w92ahcx7kt:10000
`

then after a while the log shows requests finishing after 5 minutes (example):
`2021-01-27T11:24:07.777Z [DEBUG] agent.http: Request finished: method=GET url=/v1/kv/config%2F?recurse=false&index=3412 from=127.0.0.1:49540 latency=5m6.481053631s`

finally the monitor requests start to work again (last line):
`2021-01-27T11:27:37.234Z [DEBUG] agent.http: Request finished: method=GET url=/v1/kv/?recurse=false&index=32768 from=127.0.0.1:57280 latency=5m7.514869888s`
`2021-01-27T11:27:37.426Z [DEBUG] agent.http: Request finished: method=GET url=/v1/agent/metrics?format=prometheus from=127.0.0.1:33674 latency=2.961609ms`
`2021-01-27T11:27:37.759Z [DEBUG] agent.http: Request finished: method=GET url=/v1/kv/?recurse=false&index=32768 from=127.0.0.1:57258 latency=5m9.089889818s`
`2021-01-27T11:27:38.088Z [DEBUG] agent.http: Request finished: method=GET url=/v1/kv/?recurse=false&index=32768 from=127.0.0.1:57342 latency=5m5.881932099s`
`2021-01-27T11:27:38.150Z [DEBUG] agent.http: Request finished: method=GET url=/v1/kv/?recurse=false&index=32768 from=127.0.0.1:57244 latency=5m9.982433769s`
`2021-01-27T11:27:38.421Z [DEBUG] agent.http: Request finished: method=GET url=/v1/kv/?recurse=false&index=32768 from=127.0.0.1:57276 latency=5m8.91331268s`
`2021-01-27T11:27:38.464Z [DEBUG] agent.http: Request finished: method=GET url=/v1/agent/metrics?format=prometheus from=127.0.0.1:33678 latency=8.675867ms
`

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.