HTTP 500 errors while upgrading 1.12.8 to 1.13.6
- Dominant language
- Go
- Stars
- 30.1k
- Forks
- 4.6k
- Avg merge
- 1d 18h
- Merged PRs (30d)
- 39
Description
#### Overview of the Issue
---
During the upgrade from 1.12.8 to 1.13.6, we start experiencing HTTP 500 errors
```
subscribe call failed: err="rpc error: code = InvalidArgument desc = Key is required" failure_count=13 key=tracks topic=ServiceHealth
```
in the first upgraded node. These errors are intermittent, and removing the `cached` query parameter seems to solve the issue. The only endpoint that we observe such errors is on the `GET /v1/health/service/:service` endpoint, but having said that we don't use that many other endpoints.
The setup we have is a homegrown service discovery component that uses the [Go Consul API client](https://pkg.go.dev/github.com/hashicorp/consul/api) to talk directly with the local Consul server. This component makes `GET /v1/health/service/:service` calls with a few query options, so the actual call with the query params look like this: `GET /v1/health/service/mysql?cached=&passing=1&stale=&tag=sd%3Ajob%3Dspot`.
We can independently verify this issue by doing a curl on the same node on the problematic endpoint. A few other interesting characteristic that we observed:
- the observed latency for these calls are unusually high (range of 30-60s)
- removing the `cached` query parameter works
- this issue doesn't happen across all services, and is intermittent. For example, we might have this issue for some minutes for a particular service. It will resolve by another service will end up having the same issue.
#### Reproduction Steps
I'm unsure if this is reproducible outside of the cluster we are running.
0. Create a cluster running 1.12.8
1. Upgrade the first server node from 1.12.8 to 1.13.6
2. Observe some HTTP 500 errors
### Consul info for both Client and Server
Client info
The client here is the homegrown service discovery component that uses the [Go Consul API](https://pkg.go.dev/github.com/hashicorp/consul/api@v1.13.1) package. The version we have in our `go.mod` is `1.13.1`.
Server info
```
Output from server 'consul info' command here
agent:
check_monitors = 0
check_ttls = 0
checks = 0
services = 8
build:
prerelease =
revision = 12dd8aa9
version = 1.12.8
version_metadata =
consul:
acl = disabled
bootstrap = false
known_datacenters = 1
leader = false
leader_addr = 10.12.113.44:5365
server = true
raft:
applied_index = 383532788
commit_index = 383532788
fsm_pending = 0
last_contact = 29.089309ms
last_log_index = 383532788
last_log_term = 8255
last_snapshot_index = 383530197
last_snapshot_term = 8255
latest_configuration = [{Suffrage:Voter ID:795e4315-22a7-84d8-fea8-9f7aa243d9d9 Address:10.12.84.91:5365} {Suffrage:Voter ID:f6d39715-5f19-d292-ad45-e6b3aa66ed9c Address:10.12.113.44:5365} {Suffrage:Voter ID:0bf11098-b9d1-0b36-335f-4f0451bffea3 Address:10.13.89.41:5365} {Suffrage:Voter ID:b0b0fa92-a069-fea0-1dd5-e97754297ac5 Address:10.14.59.27:5365} {Suffrage:Voter ID:78f7d7a2-b0ea-a1f4-d255-d39afe7f0073 Address:10.15.88.45:5365}]
latest_configuration_index = 0
num_peers = 4
protocol_version = 3
protocol_version_max = 3
protocol_version_min = 0
snapshot_version_max = 1
snapshot_version_min = 0
state = Follower
term = 8255
runtime:
arch = amd64
cpu_count = 32
goroutines = 5834
max_procs = 32
os = linux
version = go1.18.9
serf_lan:
coordinate_resets = 0
encrypted = false
event_queue = 0
event_time = 1439
failed = 0
health_score = 0
intent_queue = 0
left = 0
member_time = 716691
members = 1503
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 = 15378
members = 5
query_queue = 0
query_time = 1
```
```
Server agent HCL config
{
"bind_addr": "10.14.59.27",
"client_addr": "0.0.0.0",
"datacenter": "db",
"data_dir": "/srv/glimpse/consul/data",
"disable_remote_exec": true,
"disable_update_check": true,
"ui": true,
"retry_join": [
"10.12.113.44",
"10.14.59.27",
"10.12.84.91",
"10.15.88.45",
"10.13.89.41"
],
"ports": {
"dns": -1,
"http": 5361,
"https": -1,
"serf_lan": 5363,
"serf_wan": 5364,
"server": 5365
},
"enable_debug": true,
"performance": {
"raft_multiplier": 1
},
"enable_local_script_checks": true,
"telemetry": {
"prometheus_retention_time": "1m",
"disable_hostname": true
},
"server": true,
"bootstrap_expect": 3,
"retry_join_wan": [
"10.12.113.44",
"10.14.59.27",
"10.12.84.91",
"10.15.88.45",
"10.13.89.41"
]
}
```
### Operating system and Environment details
### Log Fragments
```
2023-03-30_12:19:19.37318 2023-03-30T12:19:19.373Z [ERROR] agent.rpcclient.health: subscribe call failed: err="rpc error: code = InvalidArgument desc = Key is required" failure_count=13 key=tracks topic=ServiceHealth
```
Contributor guide
Research direction
Start with GET /v1/health/service/:service on a cluster upgraded from Consul 1.12.8 to 1.13.6, using the cached, passing, stale, and tag query parameters shown here. Compare curl results with the subscribe-call error and the reported 30–60 second latency. Done means identifying why the endpoint intermittently returns HTTP 500 and whether the upgrade triggers it.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- go
- Domain
- api, distributed-systems
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 28/100