Nomad doesn't wait on StopTask from drivers before StartTask during lost alloc replacement
- Dominant language
- Go
- Stars
- 17k
- Forks
- 2.1k
- Avg merge
- 1d 9h
- Merged PRs (30d)
- 105
Description
### Nomad version
Output from `nomad version`
```
./bin/nomad version
Nomad v1.3.0-dev (9d7ea218bb2ddf9d95641f5fa7db62a5b0ae0386+CHANGES)
```
### Issue
When Nomad nodes miss heartbeats by a small window, Nomad may replace some tasks on that node before the old tasks finish stopping. This can be a problem if those tasks have resources, such as ports.
In the repro below I will show a Nomad job that asks for a dynamic port allocation. The allocation gets port 9000. When the node misses the heartbeat, Nomad will try to Stop the allocations on that node, freeing up port 9000. Once the node comes back, Nomad will try to Start allocations on it again, and re-assign 9000. However, Nomad has not waited on the Stop to finish, and so the allocation fails with a port in use error.
### Reproduction steps
To force this case I made a few patches/config to nomad
1. 0 heartbeat grace period
2. no random stagger
3. Slow the heartbeat down by 1s so it gets missed by a small window
4. Add logs to the Docker driver to show the problem
5. min/max dynamic_port_range = 9000, 9003 - just reduces the surface area and shows the problem
6. Add 5 second sleep to docker driver StopTask
I have pushed my branch [here](https://github.com/hashicorp/nomad/compare/main...benbuzbee:benbuz/port-reuse-issue-demo?expand=1)
All you have to do is
```
./bin/nomad agent -config server.hcl |& tee -i out.log
```
```
nomad job run example.nomad
```
The job is exactly `nomad job init` but with count = 2
You may have to let it run for a few minutes, but not too long, for the issue to manifest. Each missed heartbeat is a chance for this problem to happen.
#### Expected Result
Nomad does not try to place an allocation using port X on node Y until StopTask on the previous allocation using port X on node Y completes.
#### Actual Result
Nomad calls StartTask before StopTask completes
### Logs
I have attached full debug logs of my run below, but the relevent lines are here.
Nomad calls StartTask for alloc 2c902c27 to which it has assigned the dynamic port 9002, at second 39.240
However, it called StopTask on alloc 5abf09b6, which it has previously assigned port 9002, at second 39.083
StopTask takes > 5 seconds to complete, and will not free the port until second 44.452
```
2022-04-19T03:26:17.774Z [INFO] client.driver_mgr.docker: StartTask: driver=docker taskid=5abf09b6-a18e-177b-bcc5-a7d507937228/redis/12f00499 port=9002
2022-04-19T03:26:39.083Z [INFO] client.driver_mgr.docker: Begin StopTask: driver=docker taskID=5abf09b6-a18e-177b-bcc5-a7d507937228/redis/12f00499
2022-04-19T03:26:39.240Z [INFO] client.driver_mgr.docker: StartTask: driver=docker taskid=2c902c27-cf1c-1621-b44a-89a4294367d9/redis/45b48948 port=9002
2022-04-19T03:26:39.524Z [DEBUG] client.driver_mgr.docker: failed to start container: driver=docker container_id=f29b425006cba3ec49a08545922bc1d096e9a0feb680f206f664c9835d7b3170 attempt=1 error="API error (500): driver failed programming external connectivity on endpoint redis-2c902c27-cf1c-1621-b44a-89a4294367d9 (a13716d7d60f1b644c524d55757a43f0b45617f5baff272025d86debbd3ae974): Bind for 10.0.2.15:9002 failed: port is already allocated"
2022-04-19T03:26:44.452Z [INFO] client.driver_mgr.docker: End StopTask: driver=docker taskID=5abf09b6-a18e-177b-bcc5-a7d507937228/redis/12f00499
```
[issue.txt](https://github.com/hashicorp/nomad/files/8509656/issue.txt)
Contributor guide
No contributing guide indexed for this repository
Research direction
Start by running the supplied reproduction with the patched heartbeat settings, `server.hcl`, and `example.nomad`, then trace the Docker driver's StopTask and StartTask lifecycle around lost-allocation replacement. Done means Nomad waits for the previous StopTask to complete before starting a replacement that reuses the same port, avoiding the reported port-in-use failure.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- docker, go
- Domain
- devops, distributed-systems
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 35/100