hashicorp / hashicorp/nomad

Pending allocations

Open
#6,461 11 comments 0 reactions 0 assignees View on GitHub
stage/needs-investigation theme/client type/bug
Dominant language
Go
Stars
17k
Forks
2.1k
Avg merge
1d 9h
Merged PRs (30d)
105

Description

### Nomad version
Nomad v0.9.3 (c5e8b66c3789e4e7f9a83b4e188e9a937eea43ce)

### Operating system and Environment details
RHEL 7.5

### Issue
At some point all allocations placed on a node remain in pending state.

### Reproduction steps
I'm not able to reproduce this behaviour, but it happend several times on different nodes on our cluster once we updated from 0.8.4 to 0.9.3

I found out that this happens after the GC runs when allocations reach gc_max_allocs. But it doesn't happens every time.

### Nomad Client logs (if appropriate)

```
Oct 9 21:05:00 w-008a19cc-0017 nomad: {"@level":"debug","@message":"updated allocations","@module":"client","@timestamp":"2019-10-09T21:05:00.155479Z","filtered":103,"index":29757357,"pulled":15,"total":118}
Oct 9 21:05:00 w-008a19cc-0017 nomad: {"@level":"debug","@message":"allocation updates","@module":"client","@timestamp":"2019-10-09T21:05:00.155734Z","added":1,"ignored":103,"removed":0,"updated":14}
Oct 9 21:05:00 w-008a19cc-0017 nomad: {"@level":"info","@message":"garbage collecting allocation","@module":"client.gc","@timestamp":"2019-10-09T21:05:00.186512Z","alloc_id":"ea5f6df0-0140-45e5-958a-13f389d95e50","reason":"new allocations and over max (50)"}
Oct 9 21:05:00 w-008a19cc-0017 nomad: {"@level":"debug","@message":"alloc garbage collected","@module":"client.gc","@timestamp":"2019-10-09T21:05:00.186576Z","alloc_id":"ea5f6df0-0140-45e5-958a-13f389d95e50"}
Oct 9 21:05:00 w-008a19cc-0017 nomad: {"@level":"info","@message":"garbage collecting allocation","@module":"client.gc","@timestamp":"2019-10-09T21:05:00.186614Z","alloc_id":"e6ee3260-a1c9-c283-ad17-d1cb6950774d","reason":"new allocations and over max (50)"}
Oct 9 21:05:00 w-008a19cc-0017 nomad: {"@level":"info","@message":"marking allocation for GC","@module":"client.gc","@timestamp":"2019-10-09T21:05:00.188295Z","alloc_id":"e6ee3260-a1c9-c283-ad17-d1cb6950774d"}
Oct 9 21:05:00 w-008a19cc-0017 nomad: {"@level":"debug","@message":"request complete","@module":"http","@timestamp":"2019-10-09T21:05:00.466065Z","duration":277547156441,"method":"GET","path":"/v1/node/dcce6698-f6a0-8f41-7341-2949da2a0a8c/allocations?index=29756881\u0026region=es\u0026wait=300000ms"}
Oct 9 21:05:00 w-008a19cc-0017 nomad: {"@level":"debug","@message":"updated allocations","@module":"client","@timestamp":"2019-10-09T21:05:00.480566Z","filtered":103,"index":29757363,"pulled":15,"total":118}
Oct 9 21:05:00 w-008a19cc-0017 nomad: {"@level":"debug","@message":"request complete","@module":"http","@timestamp":"2019-10-09T21:05:00.830025Z","duration":270978657,"method":"GET","path":"/v1/node/dcce6698-f6a0-8f41-7341-2949da2a0a8c/allocations?index=29757357\u0026region=es\u0026wait=300000ms"}
Oct 9 21:10:02 w-008a19cc-0017 nomad: {"@level":"debug","@message":"updated allocations","@module":"client","@timestamp":"2019-10-09T21:10:02.289686Z","filtered":103,"index":29757363,"pulled":15,"total":118}
Oct 9 21:10:12 w-008a19cc-0017 nomad: {"@level":"debug","@message":"request complete","@module":"http","@timestamp":"2019-10-09T21:10:12.115422Z","duration":311206778941,"method":"GET","path":"/v1/node/dcce6698-f6a0-8f41-7341-2949da2a0a8c/allocations?index=29757363\u0026region=es\u0026wait=300000ms"}
```

As you can see in the logs, the allocation with ID: `e6ee3260-a1c9-c283-ad17-d1cb6950774d` doesn't get garbage collected.

That allocation shows the following (note that times in the log are UTC and in my PC are GMT+2):

![e6ee3260-a1c9-c283-ad17-d1cb6950774d-events](https://user-images.githubusercontent.com/6938602/66560258-4e4f1b00-eb57-11e9-8b97-cd26b6e7c990.png)

The last event is when I restarted the nomad service in the instance.
Seems like nomad is trying to garbage collect an already dead allocation.

As this happened to us several times before I enabled the profiler on the node to get some data. I saw the following (taken at Thu Oct 10 09:00:00 CEST 2019):

```
goroutine 1892 [select, 595 minutes]:
github.com/hashicorp/nomad/client.(*AllocGarbageCollector).destroyAllocRunner(0xc00048b0e0, 0xc00dc3f620, 0x24, 0x2499a00, 0xc00890cf00, 0xc0066550b0, 0x21)
/opt/gopath/src/github.com/hashicorp/nomad/client/gc.go:185 +0x2d9
github.com/hashicorp/nomad/client.(*AllocGarbageCollector).MakeRoomFor(0xc00048b0e0, 0xc001c8db70, 0x1, 0x1, 0x4, 0x4)
/opt/gopath/src/github.com/hashicorp/nomad/client/gc.go:257 +0x11a
github.com/hashicorp/nomad/client.(*Client).runAllocs(0xc00001c240, 0xc0074b0880)
/opt/gopath/src/github.com/hashicorp/nomad/client/client.go:2028 +0x6b7
github.com/hashicorp/nomad/client.(*Client).run(0xc00001c240)
/opt/gopath/src/github.com/hashicorp/nomad/client/client.go:1485 +0x91
created by github.com/hashicorp/nomad/client.NewClient
/opt/gopath/src/github.com/hashicorp/nomad/client/client.go:476 +0x16d7

goroutine 850951 [select, 17038 minutes]:
github.com/hashicorp/nomad/client.(*AllocGarbageCollector).destroyAllocRunner(0xc00048b0e0, 0xc007a421b0, 0x24, 0x2499a00, 0xc00cd63200, 0x21d83d5, 0x11)
/opt/gopath/src/github.com/hashicorp/nomad/client/gc.go:185 +0x2d9
github.com/hashicorp/nomad/client.(*AllocGarbageCollector).Collect(0xc00048b0e0, 0xc007a421b0, 0x24, 0x872c01)
/opt/gopath/src/github.com/hashicorp/nomad/client/gc.go:209 +0x196
created by github.com/hashicorp/nomad/client.(*Client).removeAlloc
/opt/gopath/src/github.com/hashicorp/nomad/client/client.go:2133 +0x39c
```
The time of first one (595 minutes) is the same that the first pending allocation had when placed on the node (Oct 9 21:05:00). The other tracks back to this moment:

```Sep 28 11:01:51 w-008a19cc-0017 nomad: {"@level":"debug","@message":"updated allocations","@module":"client","@timestamp":"2019-09-28T11:01:51.614761Z","filtered":76,"index":28028352,"pulled":0,"total":76}
Sep 28 11:01:51 w-008a19cc-0017 nomad: {"@level":"debug","@message":"allocation updates","@module":"client","@timestamp":"2019-09-28T11:01:51.614967Z","added":0,"ignored":76,"removed":1,"updated":0}
Sep 28 11:01:51 w-008a19cc-0017 nomad: {"@level":"debug","@message":"allocation updates applied","@module":"client","@timestamp":"2019-09-28T11:01:51.615038Z","added":0,"errors":0,"ignored":76,"removed":1,"updated":0}
Sep 28 11:01:51 w-008a19cc-0017 nomad: {"@level":"info","@message":"garbage collecting allocation","@module":"client.gc","@timestamp":"2019-09-28T11:01:51.615055Z","alloc_id":"049b6b85-f1d6-efb3-78ee-681f89c9ad63","reason":"forced collection"}
Sep 28 11:01:51 w-008a19cc-0017 nomad: {"@level":"debug","@message":"alloc garbage collected","@module":"client.gc","@timestamp":"2019-09-28T11:01:51.615099Z","alloc_id":"049b6b85-f1d6-efb3-78ee-681f89c9ad63"}
Sep 28 11:01:51 w-008a19cc-0017 nomad: {"@level":"debug","@message":"updated allocations","@module":"client","@timestamp":"2019-09-28T11:01:51.713433Z","filtered":74,"index":28028356,"pulled":0,"total":74}
Sep 28 11:01:51 w-008a19cc-0017 nomad: {"@level":"debug","@message":"allocation updates","@module":"client","@timestamp":"2019-09-28T11:01:51.713598Z","added":0,"ignored":74,"removed":2,"updated":0}
Sep 28 11:01:51 w-008a19cc-0017 nomad: {"@level":"debug","@message":"allocation updates applied","@module":"client","@timestamp":"2019-09-28T11:01:51.713644Z","added":0,"errors":0,"ignored":74,"removed":2,"updated":0}
Sep 28 11:01:51 w-008a19cc-0017 nomad: {"@level":"info","@message":"garbage collecting allocation","@module":"client.gc","@timestamp":"2019-09-28T11:01:51.713650Z","alloc_id":"ec8a075b-7946-7fee-303f-a02fdf53ae1a","reason":"forced collection"}
Sep 28 11:01:51 w-008a19cc-0017 nomad: {"@level":"info","@message":"garbage collecting allocation","@module":"client.gc","@timestamp":"2019-09-28T11:01:51.713660Z","alloc_id":"743b7e55-54b4-4187-5a61-494a262e969b","reason":"forced collection"}
Sep 28 11:01:51 w-008a19cc-0017 nomad: {"@level":"debug","@message":"alloc garbage collected","@module":"client.gc","@timestamp":"2019-09-28T11:01:51.724669Z","alloc_id":"743b7e55-54b4-4187-5a61-494a262e969b"}
Sep 28 11:02:49 w-008a19cc-0017 nomad: {"@level":"debug","@message":"request complete","@module":"http","@timestamp":"2019-09-28T11:02:49.646780Z","duration":311948611113,"method":"GET","path":"/v1/node/dcce6698-f6a0-8f41-7341-2949da2a0a8c/allocations?index=28023851\u0026region=es\u0026wait=300000ms"}
```

Seems like the allocation `ec8a075b-7946-7fee-303f-a02fdf53ae1a` doesnt't get correctly garbage collected either.

It seems that when the node reach `gc_max_allocs` and `gc_parallel_destroys` are blocked all allocations that are placed on that node remain pending state until the nomad service is rebooted. At least that is what I feel is happening here.

Weirdly, I thought that pending allocations would be blocking here: https://github.com/hashicorp/nomad/blob/v0.9.3/client/gc.go#L180

But no goroutines appeared there, so they must be waiting someplace else...

Contributor guide

No contributing guide indexed for this repository

Research direction

Start by tracing allocation garbage collection in client/gc.go, especially destroyAllocRunner, Collect, and MakeRoomFor, then follow the callers in client/client.go at runAllocs and removeAlloc. Compare the profiler stacks and logs around gc_max_allocs and gc_parallel_destroys. Done means allocations are no longer left pending after garbage collection, with regression coverage for the observed lifecycle.

Written by the indexing model from the issue text.

Assessment

Tech stack
go
Domain
devops, infrastructure
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.