hashicorp / hashicorp/nomad

Nomad server reports 0 allocations placed, but is wrong

Open
#9,054 10 comments 0 reactions 0 assignees View on GitHub
stage/accepted theme/batch theme/drain theme/scheduling type/bug
Dominant language
Go
Stars
17k
Forks
2.1k
Avg merge
1d 9h
Merged PRs (30d)
105

Description

### Nomad version
0.12.1

### Operating system and Environment details
unix kernel 5.4.70; debian

### Issue

We are using the API to schedule a batch job. This batch job is new - nomad has never seen it before in its current state - i know this because it has randomly generated data inside of it - though there may have been a previous job with the same name.

The API returns the following Evaluation structure indicating "no allocations were placed"

```
2020-10-08T19:44:55.335Z: {ID:53563aed-6b2d-b607-4d17-27788affbb93 Priority:50 Type:batch TriggeredBy:job-register Namespace:default JobID:browser-131m9-10100-10199 JobModifyIndex:892821 NodeID: NodeModifyIndex:0 DeploymentID: Status:complete StatusDescription: Wait:0s WaitUntil:0001-01-01 00:00:00 +0000 UTC NextEval: PreviousEval: BlockedEval: FailedTGAllocs:map[] ClassEligibility:map[] EscapedComputedClass:false QuotaLimitReached: AnnotatePlan:false QueuedAllocations:map[browsers:0] SnapshotIndex:892828 CreateIndex:892821 ModifyIndex:892830 CreateTime:1602186294990126740 ModifyTime:1602186295310028622}
```

The nomad server DEBUG logs agree, saying it ignored 2 allocs and placed 0
```
2020-10-08T19:44:55.309Z [DEBUG] worker: dequeued evaluation: eval_id=53563aed-6b2d-b607-4d17-27788affbb93
2020-10-08T19:44:55.309Z [DEBUG] worker.batch_sched: setting eval status: eval_id=53563aed-6b2d-b607-4d17-27788affbb93 job_id=browser-131m9-10100-10199 namespace=default status=complete
2020-10-08T19:44:55.309Z [DEBUG] worker.batch_sched: reconciled current state with desired state: eval_id=53563aed-6b2d-b607-4d17-27788affbb93 job_id=browser-131m9-10100-10199 namespace=default results="Total changes: (place 0) (destructive 0) (inplace 0) (stop 0)
worker: dequeued evaluation: eval_id=53563aed-6b2d-b607-4d17-27788affbb93
worker.batch_sched: reconciled current state with desired state: eval_id=53563aed-6b2d-b607-4d17-27788affbb93 job_id=browser-131m9-10100-10199 namespace=default results="Total changes: (place 0) (destructive 0) (inplace 0) (stop 0) Desired Changes for "browsers": (place 0) (inplace 0) (destructive 0) (stop 0) (migrate 0) (ignore 2) (canary 0)"
worker.batch_sched: setting eval status: eval_id=53563aed-6b2d-b607-4d17-27788affbb93 job_id=browser-131m9-10100-10199 namespace=default status=complete
```

(these logs are confusing, some have timestamps some dont, and there seem to be 2 very similar ones for a few lines)
**Question 1: Why don't the logs or the API tell me WHY it wasn't placed? The current information is not very useful.**

HOWEVER, I could confirm in the nomad client logs that it WAS placed, through some trickery. There is no proof, but you will have to trust me that I can tell by piecing together, that this run was allocation `e8699e91-91e6-e610-6d8b-0f18ba4996dd`
**Question 2: Is there some way to correlate the eval with an allocation in the server or client logs? I cannot find any.**
```
client.alloc_runner.task_runner.task_hook.logmon: starting plugin: alloc_id=e8699e91-91e6-e610-6d8b-0f18ba4996dd task=browser path=/usr/bin/nomad args=[/usr/bin/nomad, logmon]
2020-10-08T19:44:55.313Z [DEBUG] client.alloc_runner.task_runner.task_hook.logmon: waiting for RPC address: alloc_id=e8699e91-91e6-e610-6d8b-0f18ba4996dd task=browser path=/usr/bin/nomad
```
it actually runs fine for a few minutes before it stops for some reason, but I dont care about that right now

**Main bug: What happened? Why does the server thing no alloc was placed, when in fact I can see that one was?**

### Possibly related, but maybe not
The node exited drain mode less than a second before this happened
```
020-10-08T19:44:54.909Z [DEBUG] http: request complete: method=PUT path=/v1/node/aec2d08a-c72c-1166-eaca-1fbb79a373a2/drain duration=36.181106ms
020-10-08T19:44:55.030Z [DEBUG] http: request complete: method=PUT path=/v1/node/aec2d08a-c72c-1166-eaca-1fbb79a373a2/eligibility duration=1.323457ms
```

Contributor guide

No contributing guide indexed for this repository

Research direction

Start with the reported evaluation structure and the server and client DEBUG logs, comparing their timestamps and evaluation and allocation IDs. Determine why the server reports ignored allocations and zero placements while the client shows allocation e8699e91-91e6-e610-6d8b-0f18ba4996dd, and document or improve the diagnostics so placement and correlation are clear.

Written by the indexing model from the issue text.

Assessment

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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.