16159: Adds error logging on token expiration failure. Fixes SQL query.
[arvados.git] / lib / dispatchcloud / scheduler / run_queue.go
1 // Copyright (C) The Arvados Authors. All rights reserved.
2 //
3 // SPDX-License-Identifier: AGPL-3.0
4
5 package scheduler
6
7 import (
8         "sort"
9         "time"
10
11         "git.arvados.org/arvados.git/lib/dispatchcloud/container"
12         "git.arvados.org/arvados.git/sdk/go/arvados"
13         "github.com/sirupsen/logrus"
14 )
15
16 func (sch *Scheduler) runQueue() {
17         unsorted, _ := sch.queue.Entries()
18         sorted := make([]container.QueueEnt, 0, len(unsorted))
19         for _, ent := range unsorted {
20                 sorted = append(sorted, ent)
21         }
22         sort.Slice(sorted, func(i, j int) bool {
23                 return sorted[i].Container.Priority > sorted[j].Container.Priority
24         })
25
26         running := sch.pool.Running()
27         unalloc := sch.pool.Unallocated()
28
29         sch.logger.WithFields(logrus.Fields{
30                 "Containers": len(sorted),
31                 "Processes":  len(running),
32         }).Debug("runQueue")
33
34         dontstart := map[arvados.InstanceType]bool{}
35         var overquota []container.QueueEnt // entries that are unmappable because of worker pool quota
36         var containerAllocatedWorkerBootingCount int
37
38 tryrun:
39         for i, ctr := range sorted {
40                 ctr, it := ctr.Container, ctr.InstanceType
41                 logger := sch.logger.WithFields(logrus.Fields{
42                         "ContainerUUID": ctr.UUID,
43                         "InstanceType":  it.Name,
44                 })
45                 if _, running := running[ctr.UUID]; running || ctr.Priority < 1 {
46                         continue
47                 }
48                 switch ctr.State {
49                 case arvados.ContainerStateQueued:
50                         if unalloc[it] < 1 && sch.pool.AtQuota() {
51                                 logger.Debug("not locking: AtQuota and no unalloc workers")
52                                 overquota = sorted[i:]
53                                 break tryrun
54                         }
55                         if sch.pool.KillContainer(ctr.UUID, "about to lock") {
56                                 logger.Info("not locking: crunch-run process from previous attempt has not exited")
57                                 continue
58                         }
59                         go sch.lockContainer(logger, ctr.UUID)
60                         unalloc[it]--
61                 case arvados.ContainerStateLocked:
62                         if unalloc[it] > 0 {
63                                 unalloc[it]--
64                         } else if sch.pool.AtQuota() {
65                                 // Don't let lower-priority containers
66                                 // starve this one by using keeping
67                                 // idle workers alive on different
68                                 // instance types.
69                                 logger.Debug("unlocking: AtQuota and no unalloc workers")
70                                 sch.queue.Unlock(ctr.UUID)
71                                 overquota = sorted[i:]
72                                 break tryrun
73                         } else if logger.Info("creating new instance"); sch.pool.Create(it) {
74                                 // Success. (Note pool.Create works
75                                 // asynchronously and does its own
76                                 // logging, so we don't need to.)
77                         } else {
78                                 // Failed despite not being at quota,
79                                 // e.g., cloud ops throttled.  TODO:
80                                 // avoid getting starved here if
81                                 // instances of a specific type always
82                                 // fail.
83                                 continue
84                         }
85
86                         if dontstart[it] {
87                                 // We already tried & failed to start
88                                 // a higher-priority container on the
89                                 // same instance type. Don't let this
90                                 // one sneak in ahead of it.
91                         } else if sch.pool.KillContainer(ctr.UUID, "about to start") {
92                                 logger.Info("not restarting yet: crunch-run process from previous attempt has not exited")
93                         } else if sch.pool.StartContainer(it, ctr) {
94                                 // Success.
95                         } else {
96                                 containerAllocatedWorkerBootingCount += 1
97                                 dontstart[it] = true
98                         }
99                 }
100         }
101
102         sch.mContainersAllocatedNotStarted.Set(float64(containerAllocatedWorkerBootingCount))
103         sch.mContainersNotAllocatedOverQuota.Set(float64(len(overquota)))
104
105         if len(overquota) > 0 {
106                 // Unlock any containers that are unmappable while
107                 // we're at quota.
108                 for _, ctr := range overquota {
109                         ctr := ctr.Container
110                         if ctr.State == arvados.ContainerStateLocked {
111                                 logger := sch.logger.WithField("ContainerUUID", ctr.UUID)
112                                 logger.Debug("unlock because pool capacity is used by higher priority containers")
113                                 err := sch.queue.Unlock(ctr.UUID)
114                                 if err != nil {
115                                         logger.WithError(err).Warn("error unlocking")
116                                 }
117                         }
118                 }
119                 // Shut down idle workers that didn't get any
120                 // containers mapped onto them before we hit quota.
121                 for it, n := range unalloc {
122                         if n < 1 {
123                                 continue
124                         }
125                         sch.pool.Shutdown(it)
126                 }
127         }
128 }
129
130 // Lock the given container. Should be called in a new goroutine.
131 func (sch *Scheduler) lockContainer(logger logrus.FieldLogger, uuid string) {
132         if !sch.uuidLock(uuid, "lock") {
133                 return
134         }
135         defer sch.uuidUnlock(uuid)
136         if ctr, ok := sch.queue.Get(uuid); !ok || ctr.State != arvados.ContainerStateQueued {
137                 // This happens if the container has been cancelled or
138                 // locked since runQueue called sch.queue.Entries(),
139                 // possibly by a lockContainer() call from a previous
140                 // runQueue iteration. In any case, we will respond
141                 // appropriately on the next runQueue iteration, which
142                 // will have already been triggered by the queue
143                 // update.
144                 logger.WithField("State", ctr.State).Debug("container no longer queued by the time we decided to lock it, doing nothing")
145                 return
146         }
147         err := sch.queue.Lock(uuid)
148         if err != nil {
149                 logger.WithError(err).Warn("error locking container")
150                 return
151         }
152         logger.Debug("lock succeeded")
153         ctr, ok := sch.queue.Get(uuid)
154         if !ok {
155                 logger.Error("(BUG?) container disappeared from queue after Lock succeeded")
156         } else if ctr.State != arvados.ContainerStateLocked {
157                 logger.Warnf("(race?) container has state=%q after Lock succeeded", ctr.State)
158         }
159 }
160
161 // Acquire a non-blocking lock for specified UUID, returning true if
162 // successful.  The op argument is used only for debug logs.
163 //
164 // If the lock is not available, uuidLock arranges to wake up the
165 // scheduler after a short delay, so it can retry whatever operation
166 // is trying to get the lock (if that operation is still worth doing).
167 //
168 // This mechanism helps avoid spamming the controller/database with
169 // concurrent updates for any single container, even when the
170 // scheduler loop is running frequently.
171 func (sch *Scheduler) uuidLock(uuid, op string) bool {
172         sch.mtx.Lock()
173         defer sch.mtx.Unlock()
174         logger := sch.logger.WithFields(logrus.Fields{
175                 "ContainerUUID": uuid,
176                 "Op":            op,
177         })
178         if op, locked := sch.uuidOp[uuid]; locked {
179                 logger.Debugf("uuidLock not available, Op=%s in progress", op)
180                 // Make sure the scheduler loop wakes up to retry.
181                 sch.wakeup.Reset(time.Second / 4)
182                 return false
183         }
184         logger.Debug("uuidLock acquired")
185         sch.uuidOp[uuid] = op
186         return true
187 }
188
189 func (sch *Scheduler) uuidUnlock(uuid string) {
190         sch.mtx.Lock()
191         defer sch.mtx.Unlock()
192         delete(sch.uuidOp, uuid)
193 }