open-nomad/nomad/drainer/watch_jobs.go

498 lines
13 KiB
Go
Raw Normal View History

2018-03-08 23:08:23 +00:00
package drainer
2018-03-02 00:37:19 +00:00
2018-03-06 18:12:17 +00:00
import (
"context"
"fmt"
"sync"
"time"
2018-03-02 00:37:19 +00:00
2018-09-15 23:23:13 +00:00
log "github.com/hashicorp/go-hclog"
2018-03-06 18:12:17 +00:00
memdb "github.com/hashicorp/go-memdb"
2018-09-15 23:23:13 +00:00
2018-03-06 18:12:17 +00:00
"github.com/hashicorp/nomad/helper"
"github.com/hashicorp/nomad/nomad/state"
"github.com/hashicorp/nomad/nomad/structs"
"golang.org/x/time/rate"
)
2018-03-06 22:37:37 +00:00
type DrainRequest struct {
Allocs []*structs.Allocation
Resp *structs.BatchFuture
}
func NewDrainRequest(allocs []*structs.Allocation) *DrainRequest {
return &DrainRequest{
Allocs: allocs,
Resp: structs.NewBatchFuture(),
}
}
2018-03-06 18:12:17 +00:00
// DrainingJobWatcher is the interface for watching a job drain
2018-03-02 00:37:19 +00:00
type DrainingJobWatcher interface {
2018-03-06 18:12:17 +00:00
// RegisterJob is used to start watching a draining job
RegisterJobs(job []structs.NamespacedID)
2018-03-06 18:12:17 +00:00
// Drain is used to emit allocations that should be drained.
2018-03-06 22:37:37 +00:00
Drain() <-chan *DrainRequest
2018-03-06 18:12:17 +00:00
2018-03-08 00:51:57 +00:00
// Migrated is allocations for draining jobs that have transitioned to
2018-03-06 18:12:17 +00:00
// stop. There is no guarantee that duplicates won't be published.
Migrated() <-chan []*structs.Allocation
}
// drainingJobWatcher is used to watch draining jobs and emit events when
// draining allocations have replacements
type drainingJobWatcher struct {
ctx context.Context
2018-09-15 23:23:13 +00:00
logger log.Logger
2018-03-06 18:12:17 +00:00
// state is the state that is watched for state changes.
state *state.StateStore
// limiter is used to limit the rate of blocking queries
limiter *rate.Limiter
// jobs is the set of tracked jobs.
jobs map[structs.NamespacedID]struct{}
2018-03-06 18:12:17 +00:00
// queryCtx is used to cancel a blocking query.
queryCtx context.Context
queryCancel context.CancelFunc
// drainCh and migratedCh are used to emit allocations
2018-03-06 22:37:37 +00:00
drainCh chan *DrainRequest
2018-03-06 18:12:17 +00:00
migratedCh chan []*structs.Allocation
l sync.RWMutex
}
// NewDrainingJobWatcher returns a new job watcher. The caller is expected to
// cancel the context to clean up the drainer.
2018-09-15 23:23:13 +00:00
func NewDrainingJobWatcher(ctx context.Context, limiter *rate.Limiter, state *state.StateStore, logger log.Logger) *drainingJobWatcher {
2018-03-06 18:12:17 +00:00
// Create a context that can cancel the blocking query so that when a new
// job gets registered it is handled.
queryCtx, queryCancel := context.WithCancel(ctx)
w := &drainingJobWatcher{
ctx: ctx,
queryCtx: queryCtx,
queryCancel: queryCancel,
limiter: limiter,
2018-09-15 23:23:13 +00:00
logger: logger.Named("job_watcher"),
2018-03-06 18:12:17 +00:00
state: state,
jobs: make(map[structs.NamespacedID]struct{}, 64),
2018-03-08 21:25:09 +00:00
drainCh: make(chan *DrainRequest),
migratedCh: make(chan []*structs.Allocation),
2018-03-06 18:12:17 +00:00
}
go w.watch()
return w
}
// RegisterJob marks the given job as draining and adds it to being watched.
func (w *drainingJobWatcher) RegisterJobs(jobs []structs.NamespacedID) {
2018-03-06 18:12:17 +00:00
w.l.Lock()
defer w.l.Unlock()
updated := false
for _, jns := range jobs {
if _, ok := w.jobs[jns]; ok {
continue
}
// Add the job and cancel the context
2018-09-15 23:23:13 +00:00
w.logger.Trace("registering job", "job", jns)
w.jobs[jns] = struct{}{}
updated = true
2018-03-06 18:12:17 +00:00
}
if updated {
w.queryCancel()
2018-03-06 18:12:17 +00:00
// Create a new query context
w.queryCtx, w.queryCancel = context.WithCancel(w.ctx)
}
2018-03-06 18:12:17 +00:00
}
// Drain returns the channel that emits allocations to drain.
2018-03-06 22:37:37 +00:00
func (w *drainingJobWatcher) Drain() <-chan *DrainRequest {
2018-03-06 18:12:17 +00:00
return w.drainCh
}
// Migrated returns the channel that emits allocations for draining jobs that
// have been migrated.
func (w *drainingJobWatcher) Migrated() <-chan []*structs.Allocation {
return w.migratedCh
}
// deregisterJob removes the job from being watched.
func (w *drainingJobWatcher) deregisterJob(jobID, namespace string) {
w.l.Lock()
defer w.l.Unlock()
jns := structs.NamespacedID{
2018-03-06 18:12:17 +00:00
ID: jobID,
Namespace: namespace,
}
delete(w.jobs, jns)
2018-09-15 23:23:13 +00:00
w.logger.Trace("deregistering job", "job", jns)
2018-03-06 18:12:17 +00:00
}
// watch is the long lived watching routine that detects job drain changes.
func (w *drainingJobWatcher) watch() {
2018-03-07 22:57:35 +00:00
waitIndex := uint64(1)
2018-03-06 18:12:17 +00:00
for {
2018-09-15 23:23:13 +00:00
w.logger.Trace("getting job allocs at index", "index", waitIndex)
2018-03-07 22:57:35 +00:00
jobAllocs, index, err := w.getJobAllocs(w.getQueryCtx(), waitIndex)
2018-03-06 18:12:17 +00:00
if err != nil {
if err == context.Canceled {
// Determine if it is a cancel or a shutdown
select {
case <-w.ctx.Done():
return
default:
// The query context was cancelled;
// reset index so we don't miss past
// updates to newly registered jobs
waitIndex = 1
2018-03-06 18:12:17 +00:00
continue
}
}
2018-09-15 23:23:13 +00:00
w.logger.Error("error watching job allocs updates at index", "index", waitIndex, "error", err)
2018-03-06 18:12:17 +00:00
select {
case <-w.ctx.Done():
2018-09-15 23:23:13 +00:00
w.logger.Trace("shutting down")
2018-03-06 18:12:17 +00:00
return
case <-time.After(stateReadErrorDelay):
continue
}
}
avoid logging in draining job watcher In tests where the logger is a test logger, emitting a trace log in a background thread while it's shutting down may trigger a panic. Thus avoid logging Trace if err != nil. Note that we already log an error when err isn't a trace. This fixes cases where tests panic with a trace like: ``` panic: Log in goroutine after TestAllocGarbageCollector_MakeRoomFor_MaxAllocs has completed goroutine 30 [running]: testing.(*common).logDepth(0xc000aa9e60, 0xc000c4a000, 0xab, 0x3) /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:680 +0x4d3 testing.(*common).log(...) /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:662 testing.(*common).Logf(0xc000aa9e60, 0x690b941, 0x4, 0xc001366c00, 0x2, 0x2) /usr/local/Cellar/go/1.14/libexec/src/testing/testing.go:701 +0x7e github.com/hashicorp/nomad/helper/testlog.(*writer).Write(0xc000a82a60, 0xc0000b48c0, 0xab, 0x13f, 0x0, 0x0, 0x0) /Users/notnoop/go/src/github.com/hashicorp/nomad/helper/testlog/testlog.go:34 +0x106 github.com/hashicorp/nomad/vendor/github.com/hashicorp/go-hclog.(*writer).Flush(0xc000a80900, 0xbf9870f000000001, 0x20a87556e, 0x8b12bc0) /Users/notnoop/go/src/github.com/hashicorp/nomad/vendor/github.com/hashicorp/go-hclog/writer.go:29 +0x14f github.com/hashicorp/nomad/vendor/github.com/hashicorp/go-hclog.(*intLogger).log(0xc000e2c180, 0xc0003b6880, 0x17, 0x1, 0x6974edc, 0x22, 0xc000db57a0, 0x6, 0x6) /Users/notnoop/go/src/github.com/hashicorp/nomad/vendor/github.com/hashicorp/go-hclog/intlogger.go:139 +0x15d github.com/hashicorp/nomad/vendor/github.com/hashicorp/go-hclog.(*intLogger).Trace(0xc000e2c180, 0x6974edc, 0x22, 0xc000db57a0, 0x6, 0x6) /Users/notnoop/go/src/github.com/hashicorp/nomad/vendor/github.com/hashicorp/go-hclog/intlogger.go:446 +0x7a github.com/hashicorp/nomad/vendor/github.com/hashicorp/go-hclog.(*interceptLogger).Trace(0xc0002f1ad0, 0x6974edc, 0x22, 0xc000db57a0, 0x6, 0x6) /Users/notnoop/go/src/github.com/hashicorp/nomad/vendor/github.com/hashicorp/go-hclog/interceptlogger.go:48 +0x9c github.com/hashicorp/nomad/nomad/drainer.(*drainingJobWatcher).watch(0xc0002f2380) /Users/notnoop/go/src/github.com/hashicorp/nomad/nomad/drainer/watch_jobs.go:147 +0x1125 created by github.com/hashicorp/nomad/nomad/drainer.NewDrainingJobWatcher /Users/notnoop/go/src/github.com/hashicorp/nomad/nomad/drainer/watch_jobs.go:89 +0x1e3 FAIL github.com/hashicorp/nomad/client 10.605s FAIL ```
2020-03-30 01:43:25 +00:00
w.logger.Trace("retrieved allocs for draining jobs", "num_allocs", len(jobAllocs), "index", index)
2018-03-06 18:12:17 +00:00
2018-03-07 22:57:35 +00:00
lastHandled := waitIndex
waitIndex = index
2018-03-06 18:12:17 +00:00
// Snapshot the state store
snap, err := w.state.Snapshot()
if err != nil {
2018-09-15 23:23:13 +00:00
w.logger.Warn("failed to snapshot statestore", "error", err)
2018-03-06 18:12:17 +00:00
continue
}
currentJobs := w.drainingJobs()
var allDrain, allMigrated []*structs.Allocation
2018-03-07 22:57:35 +00:00
for jns, allocs := range jobAllocs {
2018-03-06 18:12:17 +00:00
// Check if the job is still registered
2018-03-07 22:57:35 +00:00
if _, ok := currentJobs[jns]; !ok {
2018-09-15 23:23:13 +00:00
w.logger.Trace("skipping job as it is no longer registered for draining", "job", jns)
2018-03-06 18:12:17 +00:00
continue
}
2018-09-15 23:23:13 +00:00
w.logger.Trace("handling job", "job", jns)
2018-03-06 18:12:17 +00:00
// Lookup the job
2018-03-19 17:18:20 +00:00
job, err := snap.JobByID(nil, jns.Namespace, jns.ID)
if err != nil {
2018-09-15 23:23:13 +00:00
w.logger.Warn("failed to lookup job", "job", jns, "error", err)
2018-03-06 18:12:17 +00:00
continue
}
2018-03-19 17:18:20 +00:00
// Ignore purged jobs
if job == nil {
2018-09-15 23:23:13 +00:00
w.logger.Trace("ignoring garbage collected job", "job", jns)
2018-03-19 17:18:20 +00:00
w.deregisterJob(jns.ID, jns.Namespace)
continue
}
2018-03-29 21:30:38 +00:00
// Ignore any system jobs
if job.Type == structs.JobTypeSystem {
2018-03-06 18:12:17 +00:00
w.deregisterJob(job.ID, job.Namespace)
continue
}
result, err := handleJob(snap, job, allocs, lastHandled)
if err != nil {
2018-09-15 23:23:13 +00:00
w.logger.Error("handling drain for job failed", "job", jns, "error", err)
2018-03-06 18:12:17 +00:00
continue
}
2018-09-15 23:23:13 +00:00
w.logger.Trace("received result for job", "job", jns, "result", result)
2018-03-07 22:57:35 +00:00
2018-03-06 18:12:17 +00:00
allDrain = append(allDrain, result.drain...)
allMigrated = append(allMigrated, result.migrated...)
// Stop tracking this job
if result.done {
w.deregisterJob(job.ID, job.Namespace)
}
}
2018-03-06 22:37:37 +00:00
if len(allDrain) != 0 {
// Create the request
req := NewDrainRequest(allDrain)
2018-09-15 23:23:13 +00:00
w.logger.Trace("sending drain request for allocs", "num_allocs", len(allDrain))
2018-03-06 22:37:37 +00:00
2018-03-06 18:12:17 +00:00
select {
2018-03-06 22:37:37 +00:00
case w.drainCh <- req:
2018-03-06 18:12:17 +00:00
case <-w.ctx.Done():
2018-09-15 23:23:13 +00:00
w.logger.Trace("shutting down")
2018-03-06 18:12:17 +00:00
return
}
2018-03-06 22:37:37 +00:00
2018-03-08 00:51:57 +00:00
// Wait for the request to be committed
2018-03-06 22:37:37 +00:00
select {
case <-req.Resp.WaitCh():
case <-w.ctx.Done():
2018-09-15 23:23:13 +00:00
w.logger.Trace("shutting down")
2018-03-06 22:37:37 +00:00
return
}
// See if it successfully committed
if err := req.Resp.Error(); err != nil {
2018-09-15 23:23:13 +00:00
w.logger.Error("failed to transition allocations", "error", err)
2018-03-06 22:37:37 +00:00
}
2018-03-07 22:57:35 +00:00
// Wait until the new index
if index := req.Resp.Index(); index > waitIndex {
waitIndex = index
}
2018-03-06 18:12:17 +00:00
}
2018-03-06 22:37:37 +00:00
if len(allMigrated) != 0 {
2018-09-15 23:23:13 +00:00
w.logger.Trace("sending migrated for allocs", "num_allocs", len(allMigrated))
2018-03-06 18:12:17 +00:00
select {
case w.migratedCh <- allMigrated:
case <-w.ctx.Done():
2018-09-15 23:23:13 +00:00
w.logger.Trace("shutting down")
2018-03-06 18:12:17 +00:00
return
}
}
}
}
// jobResult is the set of actions to take for a draining job given its current
// state.
type jobResult struct {
// drain is the set of allocations to emit for draining.
drain []*structs.Allocation
// migrated is the set of allocations to emit as migrated
migrated []*structs.Allocation
// done marks whether the job has been fully drained.
done bool
}
// newJobResult returns a jobResult with done=true. It is the responsibility of
// callers to set done=false when a remaining drainable alloc is found.
2018-03-06 18:12:17 +00:00
func newJobResult() *jobResult {
return &jobResult{
done: true,
}
}
2018-03-07 22:57:35 +00:00
func (r *jobResult) String() string {
return fmt.Sprintf("Drain %d ; Migrate %d ; Done %v", len(r.drain), len(r.migrated), r.done)
}
2018-03-06 18:12:17 +00:00
// handleJob takes the state of a draining job and returns the desired actions.
func handleJob(snap *state.StateSnapshot, job *structs.Job, allocs []*structs.Allocation, lastHandledIndex uint64) (*jobResult, error) {
r := newJobResult()
2018-03-29 21:30:38 +00:00
batch := job.Type == structs.JobTypeBatch
2018-03-06 18:12:17 +00:00
taskGroups := make(map[string]*structs.TaskGroup, len(job.TaskGroups))
for _, tg := range job.TaskGroups {
2018-03-29 21:30:38 +00:00
// Only capture the groups that have a migrate strategy or we are just
// watching batch
if tg.Migrate != nil || batch {
2018-03-06 18:12:17 +00:00
taskGroups[tg.Name] = tg
}
}
// Sort the allocations by TG
tgAllocs := make(map[string][]*structs.Allocation, len(taskGroups))
for _, alloc := range allocs {
if _, ok := taskGroups[alloc.TaskGroup]; !ok {
continue
}
tgAllocs[alloc.TaskGroup] = append(tgAllocs[alloc.TaskGroup], alloc)
}
for name, tg := range taskGroups {
allocs := tgAllocs[name]
2018-03-29 21:30:38 +00:00
if err := handleTaskGroup(snap, batch, tg, allocs, lastHandledIndex, r); err != nil {
2018-03-06 18:12:17 +00:00
return nil, fmt.Errorf("drain for task group %q failed: %v", name, err)
}
}
return r, nil
}
2018-03-29 21:30:38 +00:00
// handleTaskGroup takes the state of a draining task group and computes the
// desired actions. For batch jobs we only notify when they have been migrated
// and never mark them for drain. Batch jobs are allowed to complete up until
// the deadline, after which they are force killed.
func handleTaskGroup(snap *state.StateSnapshot, batch bool, tg *structs.TaskGroup,
2018-03-06 18:12:17 +00:00
allocs []*structs.Allocation, lastHandledIndex uint64, result *jobResult) error {
// Determine how many allocations can be drained
drainingNodes := make(map[string]bool, 4)
healthy := 0
remainingDrainingAlloc := false
var drainable []*structs.Allocation
for _, alloc := range allocs {
// Check if the alloc is on a draining node.
onDrainingNode, ok := drainingNodes[alloc.NodeID]
if !ok {
// Look up the node
node, err := snap.NodeByID(nil, alloc.NodeID)
if err != nil {
return err
}
// Check if the node exists and whether it has a drain strategy
onDrainingNode = node != nil && node.DrainStrategy != nil
drainingNodes[alloc.NodeID] = onDrainingNode
2018-03-06 18:12:17 +00:00
}
// Check if the alloc should be considered migrated. A migrated
// allocation is one that is terminal, is on a draining
// allocation, and has only happened since our last handled index to
// avoid emitting many duplicate migrate events.
if alloc.TerminalStatus() &&
onDrainingNode &&
alloc.ModifyIndex > lastHandledIndex {
result.migrated = append(result.migrated, alloc)
continue
}
2018-03-29 21:30:38 +00:00
// If the service alloc is running and has its deployment status set, it
// is considered healthy from a migration standpoint.
if !batch && !alloc.TerminalStatus() && alloc.DeploymentStatus.HasHealth() {
2018-03-06 18:12:17 +00:00
healthy++
}
// An alloc can't be considered for migration if:
// - It isn't on a draining node
// - It is already terminal
2018-03-07 22:57:35 +00:00
if !onDrainingNode || alloc.TerminalStatus() {
2018-03-06 18:12:17 +00:00
continue
}
2018-03-07 22:57:35 +00:00
// Capture the fact that there is an allocation that is still draining
// for this job.
2018-03-06 18:12:17 +00:00
remainingDrainingAlloc = true
2018-03-07 22:57:35 +00:00
// If we haven't marked this allocation for migration already, capture
// it as eligible for draining.
2018-03-29 21:30:38 +00:00
if !batch && !alloc.DesiredTransition.ShouldMigrate() {
2018-03-07 22:57:35 +00:00
drainable = append(drainable, alloc)
}
2018-03-06 18:12:17 +00:00
}
// Update the done status
if remainingDrainingAlloc {
result.done = false
}
2018-03-29 21:30:38 +00:00
// We don't mark batch for drain so exit
if batch {
return nil
}
2018-03-06 18:12:17 +00:00
// Determine how many we can drain
thresholdCount := tg.Count - tg.Migrate.MaxParallel
numToDrain := healthy - thresholdCount
numToDrain = helper.IntMin(len(drainable), numToDrain)
if numToDrain <= 0 {
return nil
}
result.drain = append(result.drain, drainable[0:numToDrain]...)
return nil
}
// getJobAllocs returns all allocations for draining jobs
func (w *drainingJobWatcher) getJobAllocs(ctx context.Context, minIndex uint64) (map[structs.NamespacedID][]*structs.Allocation, uint64, error) {
2018-03-06 18:12:17 +00:00
if err := w.limiter.Wait(ctx); err != nil {
return nil, 0, err
}
resp, index, err := w.state.BlockingQuery(w.getJobAllocsImpl, minIndex, ctx)
if err != nil {
return nil, 0, err
}
2018-03-07 22:57:35 +00:00
if resp == nil {
return nil, index, nil
}
2018-03-06 18:12:17 +00:00
return resp.(map[structs.NamespacedID][]*structs.Allocation), index, nil
2018-03-06 18:12:17 +00:00
}
// getJobAllocsImpl returns a map of draining jobs to their allocations.
func (w *drainingJobWatcher) getJobAllocsImpl(ws memdb.WatchSet, state *state.StateStore) (interface{}, uint64, error) {
index, err := state.Index("allocs")
if err != nil {
return nil, 0, err
}
// Capture the draining jobs.
draining := w.drainingJobs()
l := len(draining)
if l == 0 {
return nil, index, nil
}
// Capture the allocs for each draining job.
var maxIndex uint64 = 0
resp := make(map[structs.NamespacedID][]*structs.Allocation, l)
2018-03-06 18:12:17 +00:00
for jns := range draining {
allocs, err := state.AllocsByJob(ws, jns.Namespace, jns.ID, false)
if err != nil {
return nil, index, err
}
resp[jns] = allocs
for _, alloc := range allocs {
if maxIndex < alloc.ModifyIndex {
maxIndex = alloc.ModifyIndex
}
}
}
// Prefer using the actual max index of affected allocs since it means less
// unblocking
if maxIndex != 0 {
index = maxIndex
2018-03-06 18:12:17 +00:00
}
return resp, index, nil
}
// drainingJobs captures the set of draining jobs.
func (w *drainingJobWatcher) drainingJobs() map[structs.NamespacedID]struct{} {
2018-03-06 18:12:17 +00:00
w.l.RLock()
defer w.l.RUnlock()
l := len(w.jobs)
if l == 0 {
return nil
}
draining := make(map[structs.NamespacedID]struct{}, l)
2018-03-06 18:12:17 +00:00
for k := range w.jobs {
draining[k] = struct{}{}
}
return draining
}
// getQueryCtx is a helper for getting the query context.
func (w *drainingJobWatcher) getQueryCtx() context.Context {
w.l.RLock()
defer w.l.RUnlock()
return w.queryCtx
2018-03-02 00:37:19 +00:00
}