hashicorp / hashicorp/nomad

Client agent hangs indefinitely during shutdown

Open
#18,129 1 comment 0 reactions 0 assignees View on GitHub
hcc/jira stage/accepted theme/client type/bug
Dominant language
Go
Stars
17k
Forks
2.1k
Avg merge
1d 9h
Merged PRs (30d)
105

Description

### Nomad version
v1.5.5

### Operating system and Environment details
Unix

### Issue
There is a potential race between client shutdown and an allocation being preempted (e.g. due to priority, or due to a job update) that causes the client to hang indefinitely.

While in this state the client is still considered "up" to the servers, and so allocations continue to be scheduled on the client although it will not actually run them. This thus causes the running of those allocations to be delayed.

### Relevant Code

The rough shape of this race is as follows:
1. Client receives a new allocation that replaces another old allocation that is local to the client
2. The allocrunner blocks waiting on the termination of the old allocation
3. Client shuts down the allocrunner for the old allocation, which in turn shuts down the taskrunner for its tasks
4. Client receives a shutdown request
5. Depending on which part of the lifecycle the taskrunners in (4) are when the shutdown request is received, it might leave the task in a non-terminal state causing (2) to never be satisfied
6. Shutdown of the client blocks on shutdown of all allocrunners, and since (2) is blocked indefinitely it never shuts down and the client also doesn't shut down

**New allocrunner's `Run` function is blocked on the previous allocation becoming terminal**

When the client receives a new allocation that replaces an old allocation on the client, it creates an alloc watcher that watches the old allocation(s) which the new allocation replaces:
https://github.com/hashicorp/nomad/blob/3d63bc62b35cbe3f79cdd245d50b61f130ee1a79/client/client.go#L2602-L2621

This causes the new allocrunner's upstream-allocs prestart hook to block waiting for the old allocations to become terminal:
https://github.com/hashicorp/nomad/blob/3d63bc62b35cbe3f79cdd245d50b61f130ee1a79/client/allocrunner/upstream_allocs_hook.go#L30-L31
https://github.com/hashicorp/nomad/blob/3d63bc62b35cbe3f79cdd245d50b61f130ee1a79/client/allocwatcher/alloc_watcher.go#L274-L277

Which blocks the allocrunner's `Run` function from making progress:
https://github.com/hashicorp/nomad/blob/3d63bc62b35cbe3f79cdd245d50b61f130ee1a79/client/allocrunner/alloc_runner.go#L343

This in turn blocks the allocrunner's `Shutdown` function from finishing:
https://github.com/hashicorp/nomad/blob/3d63bc62b35cbe3f79cdd245d50b61f130ee1a79/client/allocrunner/alloc_runner.go#L1172

Which in turn blocks shutdown of the client:
https://github.com/hashicorp/nomad/blob/3d63bc62b35cbe3f79cdd245d50b61f130ee1a79/client/client.go#L858-L872

**Race causes previous allocation to be left in non-terminal state**

There are a couple of places in an taskrunner's `Run` function where a shutdown of the taskrunner can race with a kill:

https://github.com/hashicorp/nomad/blob/3d63bc62b35cbe3f79cdd245d50b61f130ee1a79/client/allocrunner/taskrunner/task_runner.go#L600-L605
https://github.com/hashicorp/nomad/blob/3d63bc62b35cbe3f79cdd245d50b61f130ee1a79/client/allocrunner/taskrunner/task_runner.go#L672-L678
https://github.com/hashicorp/nomad/blob/3d63bc62b35cbe3f79cdd245d50b61f130ee1a79/client/allocrunner/taskrunner/task_runner.go#L672-L678

My understanding is that in Go, [if multiple cases of a switch statement are satisfied at time of evaluation then there is no guarantee in which case will be picked](https://go.dev/tour/concurrency/5). So, in all of these cases, if both the `shutdownCtx` and `killCtx` are both `done` then we might end up taking the `shutdown` case and return immediately without correctly finishing the `kill`.

Most importantly, the part which marks the task as `dead` is not reached:
https://github.com/hashicorp/nomad/blob/3d63bc62b35cbe3f79cdd245d50b61f130ee1a79/client/allocrunner/taskrunner/task_runner.go#L698

Since the task is still considered live, the allocation is not transitioned to the complete/failed state. This means that the upstream-allocs hook of the new allocrunner would remain blocked.

### Reproduction steps

First, to increase the chance of the race described above happening, I injected a sleep after the prestart hooks to simulate the hooks taking some time to complete, increasing the window for the race. I also added a bunch more `shutdownCtx` cases to increase the probability of hitting that branch:

```
diff --git a/client/allocrunner/taskrunner/task_runner.go b/client/allocrunner/taskrunner/task_runner.go
index aae6a31..5143327 100644
--- a/client/allocrunner/taskrunner/task_runner.go
+++ b/client/allocrunner/taskrunner/task_runner.go
@@ -597,9 +597,22 @@ MAIN:
goto RESTART
}

+ tr.logger.Info("Sleeping a bit to simulate prestart hooks taking a while to finish")
+ time.Sleep(time.Second * 30)
+ tr.logger.Info("Done sleeping")
+
select {
case <-tr.killCtx.Done():
break MAIN
+ case <-tr.shutdownCtx.Done():
+ case <-tr.shutdownCtx.Done():
+ case <-tr.shutdownCtx.Done():
+ case <-tr.shutdownCtx.Done():
+ case <-tr.shutdownCtx.Done():
+ case <-tr.shutdownCtx.Done():
+ case <-tr.shutdownCtx.Done():
+ case <-tr.shutdownCtx.Done():
+ case <-tr.shutdownCtx.Done():
case <-tr.shutdownCtx.Done():
// TaskRunner was told to exit immediately
return
```

Then I ran the following:
```
# Start server
$ ./usr/bin/nomad agent -config server.conf
...

# Enable preemption
$ ./usr/bin/nomad operator scheduler set-config -preempt-batch-scheduler=true
Scheduler configuration updated!


# Start (patched) client
$ ./nomad-patched agent -config client-1.conf
...

# Submit low-priority job that uses port 10000
$ cat sleep-low-prio.nomad
job "low-prio" {
datacenters = ["dc1"]
type = "batch"
priority = 1

group "test-group" {
task "test-task" {
driver = "raw_exec"

config {
command = "/usr/bin/sleep"
args = ["inf"]
}

kill_timeout = "10s"
}

network {
port "test" {
static = 10000
}
}

reschedule {
attempts = 0
unlimited = false
}
}
$ ./usr/bin/nomad job run sleep-low-prio.nomad
==> 2023-07-05T12:07:33+08:00: Monitoring evaluation "08e1dc0b"
2023-07-05T12:07:33+08:00: Evaluation triggered by job "low-prio"
2023-07-05T12:07:34+08:00: Allocation "471a4855" created: node "f72e6eda", group "test-group"
2023-07-05T12:07:34+08:00: Evaluation status changed: "pending" -> "complete"
==> 2023-07-05T12:07:34+08:00: Evaluation "08e1dc0b" finished with status "complete"

# While it is sleeping, submit high-priority job that uses same port
$ cat sleep-high-prio.nomad
job "high-prio" {
datacenters = ["dc1"]
type = "batch"
priority = 100

group "test-group" {
task "test-task" {
driver = "raw_exec"

config {
command = "/usr/bin/sleep"
args = ["inf"]
}

kill_timeout = "1m"
}

network {
port "test" {
static = 10000
}
}

reschedule {
attempts = 0
unlimited = false
}
}

$ ./usr/bin/nomad job run sleep-high-prio.nomad
==> 2023-07-05T12:07:39+08:00: Monitoring evaluation "44c29be6"
2023-07-05T12:07:39+08:00: Evaluation triggered by job "high-prio"
2023-07-05T12:07:40+08:00: Allocation "673f0b58" created: node "f72e6eda", group "test-group"
2023-07-05T12:07:40+08:00: Evaluation status changed: "pending" -> "complete"
==> 2023-07-05T12:07:40+08:00: Evaluation "44c29be6" finished with status "complete"

# Once client has received the high-priority job, signal the client. Note that we are still running (or at least, pretending to) the pre-start hooks in the task runner for the low-priority job at this point.
...

# Observe that it hangs
...
```
Here are some interesting bits of the client agent's logs:
```
...
# Low-priority alloc is waiting before the select
2023-07-05T12:07:33.609+0800 [INFO] client.alloc_runner.task_runner: am waiting to simulate race: alloc_id=471a4855-155b-c5a8-ad31-8e84f58b7faa task=test-task
...
# High-priority alloc arrives and waits on the low-priority alloc to terminate
2023-07-05T12:07:39.044+0800 [DEBUG] client.alloc_watcher: waiting for previous alloc to terminate: alloc_id=673f0b58-e039-31be-e9bb-35d864c079ce previous_alloc=471a4855-155b-c5a8-ad31-8e84f58b7faa
...
# Kill requested for low-priority alloc
2023-07-05T12:07:39.044+0800 [TRACE] client.alloc_runner.task_runner: Kill requested: alloc_id=471a4855-155b-c5a8-ad31-8e84f58b7faa task=test-task
2023-07-05T12:07:39.044+0800 [TRACE] client.alloc_runner.task_runner: Kill event: alloc_id=471a4855-155b-c5a8-ad31-8e84f58b7faa task=test-task event_type=Killing event_reason=""
2023-07-05T12:07:39.044+0800 [INFO] client.alloc_runner.task_runner: Task event: alloc_id=471a4855-155b-c5a8-ad31-8e84f58b7faa task=test-task type=Killing msg="Sent interrupt. Waiting 10s before force killing" failed=false
...
# Agent is signalled
^C==> Caught signal: interrupt
2023-07-05T12:07:42.127+0800 [INFO] agent: requesting shutdown
2023-07-05T12:07:42.127+0800 [INFO] client: shutting down
# Shutdown requested for low-priority alloc
2023-07-05T12:07:42.127+0800 [TRACE] client.alloc_runner: shutting down: alloc_id=673f0b58-e039-31be-e9bb-35d864c079ce
2023-07-05T12:07:42.127+0800 [TRACE] client.alloc_runner.task_runner: shutting down: alloc_id=673f0b58-e039-31be-e9bb-35d864c079ce task=test-task
...
# Finished sleeping. Task has been requested to both be killed and shutdown at this point, triggering the race
2023-07-05T12:08:03.610+0800 [INFO] client.alloc_runner.task_runner: am before select: alloc_id=471a4855-155b-c5a8-ad31-8e84f58b7faa task=test-task
...
# Low-priority alloc is in it's final iteration of handleTaskStateUpdates
2023-07-05T12:08:03.610+0800 [TRACE] client.alloc_runner: handling task state update: alloc_id=471a4855-155b-c5a8-ad31-8e84f58b7faa done=true
...
# Final update for the alloc is sent, note that the client_status is running which is non-terminal
2023-07-05T12:08:03.610+0800 [TRACE] client.alloc_runner: sending updated alloc: alloc_id=471a4855-155b-c5a8-ad31-8e84f58b7faa client_status=running desired_status=""
...
```

I also managed to repro a similar race in the part that blocks waiting for the task to finish. Similarly, I injected a sleep to increase the probability of a race:
```
diff --git a/client/allocrunner/taskrunner/task_runner.go b/client/allocrunner/taskrunner/task_runner.go
index aae6a31..f14327a 100644
--- a/client/allocrunner/taskrunner/task_runner.go
+++ b/client/allocrunner/taskrunner/task_runner.go
@@ -630,6 +630,9 @@ MAIN:
if resultCh, err := handle.WaitCh(context.Background()); err != nil {
tr.logger.Error("wait task failed", "error", err)
} else {
+ tr.logger.Info("Sleeping a bit to simulate prestart hooks taking a while to finish")
+ time.Sleep(time.Second * 30)
+ tr.logger.Info("Done sleeping")
select {
case <-tr.killCtx.Done():
// We can go through the normal should restart check since
```
I also managed to repro this by updating a job, rather than by preemption.

#### Expected Result
The client should shut down in a timely manner.

#### Actual Result
The client blocks during shutdown, hanging indefinitely.

During this state, the client is still considered "up to the server, and thus the server continues to schedule new allocations onto the client. But because the client is stuck it never actually tries to run them. This causes the allocations to be stuck in pending state.

Contributor guide

No contributing guide indexed for this repository

Research direction

Start with client/client.go, client/allocrunner/alloc_runner.go, client/allocrunner/upstream_allocs_hook.go, client/allocwatcher/alloc_watcher.go, and client/allocrunner/taskrunner/task_runner.go at the referenced locations. Reproduce the race with allocation preemption or a job update while shutting down the client, then trace the task and allocation state transitions. Done means the client shuts down in a timely manner and replaced allocations reach a terminal state.

Written by the indexing model from the issue text.

Assessment

Tech stack
go
Domain
devops, distributed-systems
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Clearly specified
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.