hashicorp / hashicorp/consul

API request reordering due to re-election

Open
#12,879 1 comment 0 reactions 1 assignee Claimed by @Amier3 View on GitHub
theme/api type/bug
Dominant language
Go
Stars
30.1k
Forks
4.6k
Avg merge
2d 6h
Merged PRs (30d)
43

Description

#### Overview of the Issue

I have a consul cluster with 5 servers and some clients. I also have an application that will try and register as soon as session renew failed. I'm testing the case when consul leader was finished ungracefully (machine hard reboot).

The application uses [ppconsul](https://github.com/oliora/ppconsul) with it's native HTTP client (libcurl). It's not allowed to hang on consul requests for too long and uses curl option for request timeout (set to 5 seconds in that case). The application must acquire the resource (kv lock) before registration and publish this resource as service `meta`. As showed by the log, it successfully acquires the resource and tries to call `/v1/agent/service/register` which hangs for a while because of re-election.

After 5 seconds (curl request timeout) it gives up on registration and starts it's own `retry_timer` (also 5 seconds), after which it will repeat the same registration sequence. This next retry has different port in the log. It successfully acquires the resource again and calls `register`, which also hangs but is able to complete before request timeout and application receives a response.

**BUT!** After that, the previous request seem to be completed, which leads to registration being rewritten to the first (already outdated) version. This leads to application believing that it owns the resource, but registration `meta` is not accurate. The observable behaviour is application receiving response for SECOND registration and Consul discovery returning FIRST.

The questions are:

- Is "request reordering" normal? Shouldn't requests be executed in the same order they arrived, especially with such a big difference in arrival time?
- Is there a way to configure Consul to have the same request timeout as the application, so it would abandon requests that take too long to execute or just reply with an appropriate error?
- Is there some other way to handle this?

### Consul info for both Client and Server

Client info
agent:
check_monitors = 0
check_ttls = 4
checks = 7
services = 7
build:
prerelease =
revision = 2c56447e
version = 1.11.1
consul:
acl = disabled
known_servers = 5
server = false
runtime:
arch = amd64
cpu_count = 16
goroutines = 82
max_procs = 16
os = linux
version = go1.17.5
serf_lan:
coordinate_resets = 0
encrypted = false
event_queue = 0
event_time = 56
failed = 0
health_score = 0
intent_queue = 0
left = 0
member_time = 15665
members = 26
query_queue = 0
query_time = 1

### Log Fragments

```
11:48:56.213 [INFO] agent.client.memberlist.lan: memberlist: Marking core1 as failed, suspect timeout reached (2 peer confirmations)
11:48:56.214 [INFO] agent.client: removing server: server="core1 (Addr: tcp/192.0.2.70:8300) (DC: dc1)"
11:48:56.213 [INFO] agent.client.serf.lan: serf: EventMemberFailed: core1 192.0.2.70
11:48:56.357 [DEBUG] agent.client.serf.lan: serf: forgoing reconnect for random throttling
11:49:05.358 [DEBUG] agent.http: Request finished: method=GET url=/v1/coordinate/nodes from=127.0.0.1:39218 latency=422.598618ms

// Application from 127.0.0.1:39218 starts registration sequence (session-lock-register)

11:49:05.407 [DEBUG] agent.http: Request finished: method=PUT url=/v1/session/create from=127.0.0.1:39218 latency=43.973554ms
11:49:05.428 [DEBUG] agent.http: Request finished: method=PUT url=/v1/kv/id%2F22137?acquire=07374784-97c1-f8ef-c7e4-ed13089e536a from=127.0.0.1:39218 latency=20.336154ms

// Application from 127.0.0.1:39218 calls /v1/agent/service/register (timeout 5 sec) - FIRST TRY

11:49:05.586 [DEBUG] agent.client.serf.lan: serf: messageUserEventType: consul:new-leader
11:49:05.586 [INFO] agent.client: New leader elected: payload=pacemaker
11:49:05.683 [DEBUG] agent.client.serf.lan: serf: messageUserEventType: consul:new-leader
11:49:05.750 [DEBUG] agent.client.serf.lan: serf: messageUserEventType: consul:new-leader
11:49:05.764 [DEBUG] agent.client.serf.lan: serf: messageUserEventType: consul:new-leader
11:49:06.043 [DEBUG] agent.client.serf.lan: serf: messageUserEventType: consul:new-leader
11:49:06.350 [DEBUG] agent.client.serf.lan: serf: messageUserEventType: consul:new-leader
11:49:06.845 [DEBUG] agent.client.memberlist.lan: memberlist: Stream connection from=192.0.2.89:35518

// ~11:49:10.430 Application from 127.0.0.1:39218 gives up on registration - timed out

// Application waits for 5 seconds before retry
// Application from 127.0.0.1:39222 starts registration sequence (session-lock-register)

11:49:15.451 [DEBUG] agent.http: Request finished: method=PUT url=/v1/session/create from=127.0.0.1:39222 latency=11.65238ms
11:49:15.463 [DEBUG] agent.http: Request finished: method=PUT url=/v1/kv/id%2F22137?acquire=b35a0be7-be52-b858-ef36-1410bccc5b87 from=127.0.0.1:39222 latency=11.504564ms
11:49:15.474 [DEBUG] agent.http: Request finished: method=PUT url=/v1/kv/id%2F22138?acquire=b35a0be7-be52-b858-ef36-1410bccc5b87 from=127.0.0.1:39222 latency=11.312642ms

// Application from 127.0.0.1:39222 calls /v1/agent/service/register - SECOND TRY

11:49:16.464 [DEBUG] agent.client.memberlist.lan: memberlist: Initiating push/pull sync with: zookeeper3 192.0.2.96:8301
11:49:16.593 [INFO] agent.client.serf.lan: serf: EventMemberLeave (forced): core1 192.0.2.70
11:49:16.593 [DEBUG] agent.client.serf.lan: serf: messageLeaveType: core1
11:49:16.593 [INFO] agent.client: removing server: server="core1 (Addr: tcp/192.0.2.70:8300) (DC: dc1)"
11:49:16.594 [WARN] agent: grpc: addrConn.createTransport failed to connect to {dc1-192.0.2.84:8300 0 db2 }. Err :connection error: desc = "transport: Error while dialing dial tcp 192.0.2.88:0->192.0.2.84:8300: operation was canceled". Reconnecting...
11:49:16.714 [DEBUG] agent.client.serf.lan: serf: messageLeaveType: core1
11:49:16.774 [DEBUG] agent.client.serf.lan: serf: messageLeaveType: core1
11:49:18.621 [DEBUG] agent.router.manager: cycled away from server: server="core2 (Addr: tcp/192.0.2.81:8300) (DC: dc1)"
11:49:18.622 [INFO] agent.http: Request cancelled: method=PUT url=/v1/session/renew/12a3dcc4-690b-bcf4-274c-30f08c31e29f from=127.0.0.1:32992 error="rpc error making call: rpc error making call: EOF"
11:49:18.621 [ERROR] agent.client: RPC failed to server: method=Session.Renew server=192.0.2.81:8300 error="rpc error making call: rpc error making call: EOF"
11:49:18.622 [ERROR] agent: Coordinate update error: error="rpc error making call: rpc error making call: EOF"
11:49:18.621 [ERROR] agent.client: RPC failed to server: method=Coordinate.Update server=192.0.2.81:8300 error="rpc error making call: rpc error making call: EOF"
11:49:18.621 [WARN] agent: Syncing check failed.: check=service:bd503523-ad1a-4208-ad83-c4a237a3ec98 error="rpc error making call: rpc error making call: EOF"
11:49:18.621 [ERROR] agent.client: RPC failed to server: method=Catalog.Register server=192.0.2.81:8300 error="rpc error making call: rpc error making call: EOF"
11:49:18.621 [DEBUG] agent.http: Request finished: method=PUT url=/v1/session/renew/c6821b57-6dc5-81fa-626a-ef0e0e60317f from=127.0.0.1:39632 latency=29.15682158s
11:49:18.621 [ERROR] agent.http: Request error: method=PUT url=/v1/session/renew/c6821b57-6dc5-81fa-626a-ef0e0e60317f from=127.0.0.1:39632 error="rpc error making call: rpc error making call: EOF"
11:49:18.621 [ERROR] agent.client: RPC failed to server: method=Session.Renew server=192.0.2.81:8300 error="rpc error making call: rpc error making call: EOF"
11:49:18.621 [DEBUG] agent.http: Request finished: method=PUT url=/v1/session/create from=127.0.0.1:39210 latency=23.691486872s
11:49:18.621 [INFO] agent.http: Request cancelled: method=PUT url=/v1/session/create from=127.0.0.1:39210 error="rpc error making call: rpc error making call: EOF"
11:49:18.622 [DEBUG] agent: check state expired, not restoring: check=service:66595886-934c-4885-9c14-12b83b613880-exporter
11:49:18.621 [ERROR] agent.anti_entropy: failed to sync changes: error="rpc error making call: rpc error making call: EOF"
11:49:18.622 [DEBUG] agent.http: Request finished: method=PUT url=/v1/session/renew/12a3dcc4-690b-bcf4-274c-30f08c31e29f from=127.0.0.1:32992 latency=28.695688967s

// Application from 127.0.0.1:39222(!) registered - SECOND try

11:49:18.739 [DEBUG] agent.http: Request finished: method=PUT url=/v1/agent/service/register from=127.0.0.1:39222 latency=3.26438406s

// Application from 127.0.0.1:39218(!) registered - FIRST try

11:49:18.755 [DEBUG] agent.http: Request finished: method=PUT url=/v1/agent/service/register from=127.0.0.1:39218 latency=13.326624939s
```

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.