Nomad Client stuck initializing
- Dominant language
- Go
- Stars
- 17k
- Forks
- 2.1k
- Avg merge
- 1d 9h
- Merged PRs (30d)
- 105
Description
### Nomad version
```
Nomad v1.6.1
BuildDate 2023-07-21T13:49:42Z
Revision 515895c7690cdc72278018dc5dc58aca41204ccc
```
### Operating system and Environment details
```
Debian GNU/Linux 11 (bullseye)
```
### Issue
After a client restart, node gets stuck in `initializing` state. Once it gets stuck, only a restart makes it recover.
```
nomad node status -verbose
ID Node Pool DC Name Class Address Version Drain Eligibility Status
3de7fa5a-336f-d976-1c14-7a6caafd564e default acme s505.acme.com storage 10.5.1.210 1.6.1 false eligible ready
fa18d47e-c16e-947a-958b-6486a862516a default acme s402.acme.com storage 10.5.1.203 1.6.1 false eligible ready
7d0e570c-0615-34a4-227b-568e8af91ca5 default acme s403.acme.com storage 10.5.1.205 1.6.1 false eligible ready
625b55d4-b763-ee41-8b5c-bd93ee15cfec default acme s502.acme.com storage 10.5.1.204 1.6.1 false eligible ready
23523791-f4d1-499c-834c-3af34d0d6ffb default acme s501.acme.com storage 10.5.1.202 1.6.1 false eligible ready
34612ebb-4418-3d2d-bf70-0e188451429e default acme s404.acme.com storage 10.5.1.207 1.6.1 false eligible ready
a6fee44f-5398-dae6-049d-e65548f5d076 default acme s506.acme.com storage 10.5.1.212 1.6.1 false eligible ready
7adfb092-6b29-6dab-12bf-afe5a6b6c900 default acme s405.acme.com storage 10.5.1.209 1.6.1 false eligible ready
eadfd1af-91d8-860c-3a81-022bb94c9db5 default acme s503.acme.com storage 10.5.1.206 1.6.1 false eligible initializing
```
```
nomad node status -verbose eadfd1af-91d8-860c-3a81-022bb94c9db5
ID = eadfd1af-91d8-860c-3a81-022bb94c9db5
Name = s503.acme.com
Node Pool = default
Class = storage
DC = acme
Drain = false
Eligibility = eligible
Status = initializing
CSI Controllers =
CSI Drivers =
Uptime = 4840h58m33s
Host Volumes
Name ReadOnly Source
blob-storage false /data/blob-storage
Drivers
Driver Detected Healthy Message Time
docker true true Healthy 2023-09-20T13:35:08Z
exec true true Healthy 2023-09-20T13:35:08Z
java false false 2023-09-20T13:35:08Z
qemu false false 2023-09-20T13:35:08Z
raw_exec false false disabled 2023-09-20T13:35:08Z
Node Events
Time Subsystem Message Details
2023-09-20T13:35:08Z Cluster Node heartbeat missed
2023-05-30T12:03:16Z Cluster Node re-registered
2023-05-30T11:48:28Z Cluster Node heartbeat missed
2023-03-03T07:35:38Z Cluster Node re-registered
2023-03-03T00:56:25Z Cluster Node heartbeat missed
2022-11-22T14:25:24Z Cluster Node registered
```
So far, every time we experience this problem, the node contains a `Node heartbeat missed` event.
### Reproduction steps
We don't know how to reproduce it yet.
#### Expected Result
Client restarts and eventually transition to `ready` state.
#### Actual Result
Client restarts and might get stuck in `initializing` state
### Nomad Server logs (if appropriate)
```
Sep 20 01:17:40 c206.acme.com nomad-server[3895982]: 2023-09-20T01:17:40.782Z [INFO] nomad.raft: starting snapshot up to: index=1589250
Sep 20 01:17:40 c206.acme.com nomad-server[3895982]: 2023-09-20T01:17:40.782Z [INFO] snapshot: creating new snapshot: path=/data/service/nomad-server/data/server/raft/snapshots/589114-1589250-1695172660782.tmp
Sep 20 01:17:40 c206.acme.com nomad-server[3895982]: 2023-09-20T01:17:40.905Z [INFO] snapshot: reaping snapshot: path=/data/service/nomad-server/data/server/raft/snapshots/589114-1572852-1694931874411
Sep 20 01:17:40 c206.acme.com nomad-server[3895982]: 2023-09-20T01:17:40.906Z [INFO] nomad.raft: compacting logs: from=1570815 to=1579010
Sep 20 01:17:40 c206.acme.com nomad-server[3895982]: 2023-09-20T01:17:40.958Z [INFO] nomad.raft: snapshot complete up to: index=1589250
Sep 20 13:33:33 c206.acme.com nomad-server[3895982]: 2023-09-20T13:33:33.748Z [WARN] nomad.heartbeat: node TTL expired: node_id=3c6f37a6-d45d-925d-90de-0ddc7321d679
Sep 20 13:34:26 c206.acme.com nomad-server[3895982]: 2023-09-20T13:34:26.565Z [WARN] nomad.heartbeat: node TTL expired: node_id=f6b4703e-bdca-a959-90b8-60637a165592
Sep 20 13:35:08 c206.acme.com nomad-server[3895982]: 2023-09-20T13:35:08.316Z [WARN] nomad.heartbeat: node TTL expired: node_id=eadfd1af-91d8-860c-3a81-022bb94c9db5
```
### Nomad Client logs (if appropriate)
```
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.435Z [INFO] client.plugin: starting plugin manager: plugin-type=driver
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.435Z [INFO] client.plugin: starting plugin manager: plugin-type=device
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.469Z [INFO] client.alloc_runner.task_runner: Task event: alloc_id=102852d4-8b75-e5b4-fdb3-03319ee6c8bc task=apigw-envoy-be type=Received msg="Task received by client" failed=false
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.470Z [INFO] client.alloc_runner.task_runner: Task event: alloc_id=102852d4-8b75-e5b4-fdb3-03319ee6c8bc task=proxy-init type=Received msg="Task received by client" failed=false
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.483Z [INFO] client.alloc_runner.task_runner: Task event: alloc_id=491e3dfa-68d2-61d3-2971-3f459c98fe91 task=tag-sync type=Received msg="Task received by client" failed=false
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.490Z [INFO] client.alloc_runner.task_runner: Task event: alloc_id=61647409-6e33-b6d8-5275-cc1aac95da1b task=kde-planner type=Received msg="Task received by client" failed=false
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.498Z [INFO] client.alloc_runner.task_runner: Task event: alloc_id=a1e0d299-5b7d-e551-d885-7589b6472986 task=kde-cache type=Received msg="Task received by client" failed=false
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.503Z [INFO] client.alloc_runner.task_runner: Task event: alloc_id=ed544457-3a35-6b86-5219-1b1b205365b6 task=controlplane-agent type=Received msg="Task received by client" failed=false
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.517Z [INFO] client.alloc_runner.task_runner: Task event: alloc_id=fcacf1a5-10f3-29cb-618e-e51b937fa6da task=kde-worker-b type=Received msg="Task received by client" failed=false
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.523Z [INFO] client: started client: node_id=eadfd1af-91d8-860c-3a81-022bb94c9db5
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.523Z [INFO] client: node registration complete
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.570Z [WARN] client.alloc_runner.task_runner.task_hook.api: error creating task api socket: alloc_id=ed544457-3a35-6b86-5219-1b1b205365b6 task=controlplane-agent path=/data/service/nomad-client/data/alloc/ed544457-3a35-6b86-5219-1b1b205365b6/controlplane-agent/secrets/api.sock error="listen>
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.612Z [INFO] agent: (runner) creating new runner (dry: false, once: false)
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.614Z [INFO] agent: (runner) creating watcher
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.614Z [INFO] agent: (runner) starting
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.652Z [INFO] agent: (runner) creating new runner (dry: false, once: false)
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.653Z [INFO] agent: (runner) creating watcher
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.653Z [INFO] agent: (runner) starting
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.680Z [INFO] agent: (runner) creating new runner (dry: false, once: false)
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.682Z [INFO] agent: (runner) creating watcher
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.682Z [INFO] agent: (runner) starting
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.710Z [INFO] agent: (runner) creating new runner (dry: false, once: false)
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.711Z [INFO] agent: (runner) creating watcher
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.712Z [INFO] agent: (runner) starting
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.741Z [INFO] agent: (runner) creating new runner (dry: false, once: false)
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.742Z [INFO] agent: (runner) creating watcher
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.743Z [INFO] agent: (runner) starting
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.783Z [INFO] agent: (runner) creating new runner (dry: false, once: false)
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.784Z [INFO] agent: (runner) creating watcher
Sep 20 13:35:08 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:08.784Z [INFO] agent: (runner) starting
Sep 20 13:35:18 s503.acme.com nomad-client[2331106]: 2023-09-20T13:35:18.070Z [INFO] client: node registration complete
```
Contributor guide
No contributing guide indexed for this repository
Research direction
Start by tracing the Nomad client registration and heartbeat handling around the reported `Node heartbeat missed` event, using the client and server log excerpts as the initial case. Investigate why the node remains `initializing` after registration and define a reproducible scenario; done means a restarted client reliably transitions to `ready` without requiring another restart.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- go
- Domain
- distributed-systems, infrastructure
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 30/100