19175: Merge branch 'main' into 19175-doc-refactor-multi-host-installation
[arvados.git] / lib / dispatchcloud / worker / worker.go
1 // Copyright (C) The Arvados Authors. All rights reserved.
2 //
3 // SPDX-License-Identifier: AGPL-3.0
4
5 package worker
6
7 import (
8         "bytes"
9         "fmt"
10         "path/filepath"
11         "strings"
12         "sync"
13         "time"
14
15         "git.arvados.org/arvados.git/lib/cloud"
16         "git.arvados.org/arvados.git/sdk/go/arvados"
17         "git.arvados.org/arvados.git/sdk/go/stats"
18         "github.com/sirupsen/logrus"
19 )
20
21 const (
22         // TODO: configurable
23         maxPingFailTime = 10 * time.Minute
24 )
25
26 // State indicates whether a worker is available to do work, and (if
27 // not) whether/when it is expected to become ready.
28 type State int
29
30 const (
31         StateUnknown  State = iota // might be running a container already
32         StateBooting               // instance is booting
33         StateIdle                  // instance booted, no containers are running
34         StateRunning               // instance is running one or more containers
35         StateShutdown              // worker has stopped monitoring the instance
36 )
37
38 var stateString = map[State]string{
39         StateUnknown:  "unknown",
40         StateBooting:  "booting",
41         StateIdle:     "idle",
42         StateRunning:  "running",
43         StateShutdown: "shutdown",
44 }
45
46 // String implements fmt.Stringer.
47 func (s State) String() string {
48         return stateString[s]
49 }
50
51 // MarshalText implements encoding.TextMarshaler so a JSON encoding of
52 // map[State]anything uses the state's string representation.
53 func (s State) MarshalText() ([]byte, error) {
54         return []byte(stateString[s]), nil
55 }
56
57 // BootOutcome is the result of a worker boot. It is used as a label in a metric.
58 type BootOutcome string
59
60 const (
61         BootOutcomeFailed      BootOutcome = "failure"
62         BootOutcomeSucceeded   BootOutcome = "success"
63         BootOutcomeAborted     BootOutcome = "aborted"
64         BootOutcomeDisappeared BootOutcome = "disappeared"
65 )
66
67 var validBootOutcomes = map[BootOutcome]bool{
68         BootOutcomeFailed:      true,
69         BootOutcomeSucceeded:   true,
70         BootOutcomeAborted:     true,
71         BootOutcomeDisappeared: true,
72 }
73
74 // IdleBehavior indicates the behavior desired when a node becomes idle.
75 type IdleBehavior string
76
77 const (
78         IdleBehaviorRun   IdleBehavior = "run"   // run containers, or shutdown on idle timeout
79         IdleBehaviorHold  IdleBehavior = "hold"  // don't shutdown or run more containers
80         IdleBehaviorDrain IdleBehavior = "drain" // shutdown immediately when idle
81 )
82
83 var validIdleBehavior = map[IdleBehavior]bool{
84         IdleBehaviorRun:   true,
85         IdleBehaviorHold:  true,
86         IdleBehaviorDrain: true,
87 }
88
89 type worker struct {
90         logger   logrus.FieldLogger
91         executor Executor
92         wp       *Pool
93
94         mtx                 sync.Locker // must be wp's Locker.
95         state               State
96         idleBehavior        IdleBehavior
97         instance            cloud.Instance
98         instType            arvados.InstanceType
99         vcpus               int64
100         memory              int64
101         appeared            time.Time
102         probed              time.Time
103         updated             time.Time
104         busy                time.Time
105         destroyed           time.Time
106         firstSSHConnection  time.Time
107         lastUUID            string
108         running             map[string]*remoteRunner // remember to update state idle<->running when this changes
109         starting            map[string]*remoteRunner // remember to update state idle<->running when this changes
110         probing             chan struct{}
111         bootOutcomeReported bool
112         timeToReadyReported bool
113         staleRunLockSince   time.Time
114 }
115
116 func (wkr *worker) onUnkillable(uuid string) {
117         wkr.mtx.Lock()
118         defer wkr.mtx.Unlock()
119         logger := wkr.logger.WithField("ContainerUUID", uuid)
120         if wkr.idleBehavior == IdleBehaviorHold {
121                 logger.Warn("unkillable container, but worker has IdleBehavior=Hold")
122                 return
123         }
124         logger.Warn("unkillable container, draining worker")
125         wkr.setIdleBehavior(IdleBehaviorDrain)
126 }
127
128 func (wkr *worker) onKilled(uuid string) {
129         wkr.mtx.Lock()
130         defer wkr.mtx.Unlock()
131         wkr.closeRunner(uuid)
132         go wkr.wp.notify()
133 }
134
135 // caller must have lock.
136 func (wkr *worker) reportBootOutcome(outcome BootOutcome) {
137         if wkr.bootOutcomeReported {
138                 return
139         }
140         if wkr.wp.mBootOutcomes != nil {
141                 wkr.wp.mBootOutcomes.WithLabelValues(string(outcome)).Inc()
142         }
143         wkr.bootOutcomeReported = true
144 }
145
146 // caller must have lock.
147 func (wkr *worker) reportTimeBetweenFirstSSHAndReadyForContainer() {
148         if wkr.timeToReadyReported {
149                 return
150         }
151         if wkr.wp.mTimeToSSH != nil {
152                 wkr.wp.mTimeToReadyForContainer.Observe(time.Since(wkr.firstSSHConnection).Seconds())
153         }
154         wkr.timeToReadyReported = true
155 }
156
157 // caller must have lock.
158 func (wkr *worker) setIdleBehavior(idleBehavior IdleBehavior) {
159         wkr.logger.WithField("IdleBehavior", idleBehavior).Info("set idle behavior")
160         wkr.idleBehavior = idleBehavior
161         wkr.saveTags()
162         wkr.shutdownIfIdle()
163 }
164
165 // caller must have lock.
166 func (wkr *worker) startContainer(ctr arvados.Container) {
167         logger := wkr.logger.WithFields(logrus.Fields{
168                 "ContainerUUID": ctr.UUID,
169                 "Priority":      ctr.Priority,
170         })
171         logger.Debug("starting container")
172         rr := newRemoteRunner(ctr.UUID, wkr)
173         wkr.starting[ctr.UUID] = rr
174         if wkr.state != StateRunning {
175                 wkr.state = StateRunning
176                 go wkr.wp.notify()
177         }
178         go func() {
179                 rr.Start()
180                 if wkr.wp.mTimeFromQueueToCrunchRun != nil {
181                         wkr.wp.mTimeFromQueueToCrunchRun.Observe(time.Since(ctr.CreatedAt).Seconds())
182                 }
183                 wkr.mtx.Lock()
184                 defer wkr.mtx.Unlock()
185                 now := time.Now()
186                 wkr.updated = now
187                 wkr.busy = now
188                 delete(wkr.starting, ctr.UUID)
189                 wkr.running[ctr.UUID] = rr
190                 wkr.lastUUID = ctr.UUID
191         }()
192 }
193
194 // ProbeAndUpdate conducts appropriate boot/running probes (if any)
195 // for the worker's current state. If a previous probe is still
196 // running, it does nothing.
197 //
198 // It should be called in a new goroutine.
199 func (wkr *worker) ProbeAndUpdate() {
200         select {
201         case wkr.probing <- struct{}{}:
202                 wkr.probeAndUpdate()
203                 <-wkr.probing
204         default:
205                 wkr.logger.Debug("still waiting for last probe to finish")
206         }
207 }
208
209 // probeAndUpdate calls probeBooted and/or probeRunning if needed, and
210 // updates state accordingly.
211 //
212 // In StateUnknown: Call both probeBooted and probeRunning.
213 // In StateBooting: Call probeBooted; if successful, call probeRunning.
214 // In StateRunning: Call probeRunning.
215 // In StateIdle: Call probeRunning.
216 // In StateShutdown: Do nothing.
217 //
218 // If both probes succeed, wkr.state changes to
219 // StateIdle/StateRunning.
220 //
221 // If probeRunning succeeds, wkr.running is updated. (This means
222 // wkr.running might be non-empty even in StateUnknown, if the boot
223 // probe failed.)
224 //
225 // probeAndUpdate should be called in a new goroutine.
226 func (wkr *worker) probeAndUpdate() {
227         wkr.mtx.Lock()
228         updated := wkr.updated
229         initialState := wkr.state
230         wkr.mtx.Unlock()
231
232         var (
233                 booted   bool
234                 ctrUUIDs []string
235                 ok       bool
236                 stderr   []byte // from probeBooted
237         )
238
239         switch initialState {
240         case StateShutdown:
241                 return
242         case StateIdle, StateRunning:
243                 booted = true
244         case StateUnknown, StateBooting:
245         default:
246                 panic(fmt.Sprintf("unknown state %s", initialState))
247         }
248
249         probeStart := time.Now()
250         logger := wkr.logger.WithField("ProbeStart", probeStart)
251
252         if !booted {
253                 booted, stderr = wkr.probeBooted()
254                 if !booted {
255                         // Pretend this probe succeeded if another
256                         // concurrent attempt succeeded.
257                         wkr.mtx.Lock()
258                         booted = wkr.state == StateRunning || wkr.state == StateIdle
259                         wkr.mtx.Unlock()
260                 }
261                 if booted {
262                         logger.Info("instance booted; will try probeRunning")
263                 }
264         }
265         reportedBroken := false
266         if booted || wkr.state == StateUnknown {
267                 ctrUUIDs, reportedBroken, ok = wkr.probeRunning()
268         }
269         wkr.mtx.Lock()
270         defer wkr.mtx.Unlock()
271         if reportedBroken && wkr.idleBehavior == IdleBehaviorRun {
272                 logger.Info("probe reported broken instance")
273                 wkr.reportBootOutcome(BootOutcomeFailed)
274                 wkr.setIdleBehavior(IdleBehaviorDrain)
275         }
276         if !ok || (!booted && len(ctrUUIDs) == 0 && len(wkr.running) == 0) {
277                 if wkr.state == StateShutdown && wkr.updated.After(updated) {
278                         // Skip the logging noise if shutdown was
279                         // initiated during probe.
280                         return
281                 }
282                 // Using the start time of the probe as the timeout
283                 // threshold ensures we always initiate at least one
284                 // probe attempt after the boot/probe timeout expires
285                 // (otherwise, a slow probe failure could cause us to
286                 // shutdown an instance even though it did in fact
287                 // boot/recover before the timeout expired).
288                 dur := probeStart.Sub(wkr.probed)
289                 if wkr.shutdownIfBroken(dur) {
290                         // stderr from failed run-probes will have
291                         // been logged already, but boot-probe
292                         // failures are normal so they are logged only
293                         // at Debug level. This is our chance to log
294                         // some evidence about why the node never
295                         // booted, even in non-debug mode.
296                         if !booted {
297                                 wkr.reportBootOutcome(BootOutcomeFailed)
298                                 logger.WithFields(logrus.Fields{
299                                         "Duration": dur,
300                                         "stderr":   string(stderr),
301                                 }).Info("boot failed")
302                         }
303                 }
304                 return
305         }
306
307         updateTime := time.Now()
308         wkr.probed = updateTime
309
310         if updated != wkr.updated {
311                 // Worker was updated after the probe began, so
312                 // wkr.running might have a container UUID that was
313                 // not yet running when ctrUUIDs was generated. Leave
314                 // wkr.running alone and wait for the next probe to
315                 // catch up on any changes.
316                 logger.WithFields(logrus.Fields{
317                         "updated":     updated,
318                         "wkr.updated": wkr.updated,
319                 }).Debug("skipping worker state update due to probe/sync race")
320                 return
321         }
322
323         if len(ctrUUIDs) > 0 {
324                 wkr.busy = updateTime
325                 wkr.lastUUID = ctrUUIDs[0]
326         } else if len(wkr.running) > 0 {
327                 // Actual last-busy time was sometime between wkr.busy
328                 // and now. Now is the earliest opportunity to take
329                 // advantage of the non-busy state, though.
330                 wkr.busy = updateTime
331         }
332
333         changed := wkr.updateRunning(ctrUUIDs)
334
335         // Update state if this was the first successful boot-probe.
336         if booted && (wkr.state == StateUnknown || wkr.state == StateBooting) {
337                 if wkr.state == StateBooting {
338                         wkr.reportTimeBetweenFirstSSHAndReadyForContainer()
339                 }
340                 // Note: this will change again below if
341                 // len(wkr.starting)+len(wkr.running) > 0.
342                 wkr.state = StateIdle
343                 changed = true
344         }
345
346         // If wkr.state and wkr.running aren't changing then there's
347         // no need to log anything, notify the scheduler, move state
348         // back and forth between idle/running, etc.
349         if !changed {
350                 return
351         }
352
353         // Log whenever a run-probe reveals crunch-run processes
354         // appearing/disappearing before boot-probe succeeds.
355         if wkr.state == StateUnknown && changed {
356                 logger.WithFields(logrus.Fields{
357                         "RunningContainers": len(wkr.running),
358                         "State":             wkr.state,
359                 }).Info("crunch-run probe succeeded, but boot probe is still failing")
360         }
361
362         if wkr.state == StateIdle && len(wkr.starting)+len(wkr.running) > 0 {
363                 wkr.state = StateRunning
364         } else if wkr.state == StateRunning && len(wkr.starting)+len(wkr.running) == 0 {
365                 wkr.state = StateIdle
366         }
367         wkr.updated = updateTime
368         if booted && (initialState == StateUnknown || initialState == StateBooting) {
369                 wkr.reportBootOutcome(BootOutcomeSucceeded)
370                 logger.WithFields(logrus.Fields{
371                         "RunningContainers": len(wkr.running),
372                         "State":             wkr.state,
373                 }).Info("probes succeeded, instance is in service")
374         }
375         go wkr.wp.notify()
376 }
377
378 func (wkr *worker) probeRunning() (running []string, reportsBroken, ok bool) {
379         cmd := wkr.wp.runnerCmd + " --list"
380         if u := wkr.instance.RemoteUser(); u != "root" {
381                 cmd = "sudo " + cmd
382         }
383         before := time.Now()
384         stdout, stderr, err := wkr.executor.Execute(nil, cmd, nil)
385         if err != nil {
386                 wkr.logger.WithFields(logrus.Fields{
387                         "Command": cmd,
388                         "stdout":  string(stdout),
389                         "stderr":  string(stderr),
390                 }).WithError(err).Warn("probe failed")
391                 wkr.wp.mRunProbeDuration.WithLabelValues("fail").Observe(time.Now().Sub(before).Seconds())
392                 return
393         }
394         wkr.logger.WithFields(logrus.Fields{
395                 "Command": cmd,
396                 "stdout":  string(stdout),
397                 "stderr":  string(stderr),
398         }).Debug("probe succeeded")
399         wkr.wp.mRunProbeDuration.WithLabelValues("success").Observe(time.Now().Sub(before).Seconds())
400         ok = true
401
402         staleRunLock := false
403         for _, s := range strings.Split(string(stdout), "\n") {
404                 // Each line of the "crunch-run --list" output is one
405                 // of the following:
406                 //
407                 // * a container UUID, indicating that processes
408                 //   related to that container are currently running.
409                 //   Optionally followed by " stale", indicating that
410                 //   the crunch-run process itself has exited (the
411                 //   remaining process is probably arv-mount).
412                 //
413                 // * the string "broken", indicating that the instance
414                 //   appears incapable of starting containers.
415                 //
416                 // See ListProcesses() in lib/crunchrun/background.go.
417                 if s == "" {
418                         // empty string following final newline
419                 } else if s == "broken" {
420                         reportsBroken = true
421                 } else if toks := strings.Split(s, " "); len(toks) == 1 {
422                         running = append(running, s)
423                 } else if toks[1] == "stale" {
424                         wkr.logger.WithField("ContainerUUID", toks[0]).Info("probe reported stale run lock")
425                         staleRunLock = true
426                 }
427         }
428         wkr.mtx.Lock()
429         defer wkr.mtx.Unlock()
430         if !staleRunLock {
431                 wkr.staleRunLockSince = time.Time{}
432         } else if wkr.staleRunLockSince.IsZero() {
433                 wkr.staleRunLockSince = time.Now()
434         } else if dur := time.Now().Sub(wkr.staleRunLockSince); dur > wkr.wp.timeoutStaleRunLock {
435                 wkr.logger.WithField("Duration", dur).Warn("reporting broken after reporting stale run lock for too long")
436                 reportsBroken = true
437         }
438         return
439 }
440
441 func (wkr *worker) probeBooted() (ok bool, stderr []byte) {
442         cmd := wkr.wp.bootProbeCommand
443         if cmd == "" {
444                 cmd = "true"
445         }
446         stdout, stderr, err := wkr.executor.Execute(nil, cmd, nil)
447         logger := wkr.logger.WithFields(logrus.Fields{
448                 "Command": cmd,
449                 "stdout":  string(stdout),
450                 "stderr":  string(stderr),
451         })
452         if err != nil {
453                 logger.WithError(err).Debug("boot probe failed")
454                 return false, stderr
455         }
456         logger.Info("boot probe succeeded")
457         if err = wkr.wp.loadRunnerData(); err != nil {
458                 wkr.logger.WithError(err).Warn("cannot boot worker: error loading runner binary")
459                 return false, stderr
460         } else if len(wkr.wp.runnerData) == 0 {
461                 // Assume crunch-run is already installed
462         } else if _, stderr2, err := wkr.copyRunnerData(); err != nil {
463                 wkr.logger.WithError(err).WithField("stderr", string(stderr2)).Warn("error copying runner binary")
464                 return false, stderr2
465         } else {
466                 stderr = append(stderr, stderr2...)
467         }
468         return true, stderr
469 }
470
471 func (wkr *worker) copyRunnerData() (stdout, stderr []byte, err error) {
472         hash := fmt.Sprintf("%x", wkr.wp.runnerMD5)
473         dstdir, _ := filepath.Split(wkr.wp.runnerCmd)
474         logger := wkr.logger.WithFields(logrus.Fields{
475                 "hash": hash,
476                 "path": wkr.wp.runnerCmd,
477         })
478
479         stdout, stderr, err = wkr.executor.Execute(nil, `md5sum `+wkr.wp.runnerCmd, nil)
480         if err == nil && len(stderr) == 0 && bytes.Equal(stdout, []byte(hash+"  "+wkr.wp.runnerCmd+"\n")) {
481                 logger.Info("runner binary already exists on worker, with correct hash")
482                 return
483         }
484
485         // Note touch+chmod come before writing data, to avoid the
486         // possibility of md5 being correct while file mode is
487         // incorrect.
488         cmd := `set -e; dstdir="` + dstdir + `"; dstfile="` + wkr.wp.runnerCmd + `"; mkdir -p "$dstdir"; touch "$dstfile"; chmod 0755 "$dstdir" "$dstfile"; cat >"$dstfile"`
489         if wkr.instance.RemoteUser() != "root" {
490                 cmd = `sudo sh -c '` + strings.Replace(cmd, "'", "'\\''", -1) + `'`
491         }
492         logger.WithField("cmd", cmd).Info("installing runner binary on worker")
493         stdout, stderr, err = wkr.executor.Execute(nil, cmd, bytes.NewReader(wkr.wp.runnerData))
494         return
495 }
496
497 // caller must have lock.
498 func (wkr *worker) shutdownIfBroken(dur time.Duration) bool {
499         if wkr.idleBehavior == IdleBehaviorHold {
500                 // Never shut down.
501                 return false
502         }
503         label, threshold := "", wkr.wp.timeoutProbe
504         if wkr.state == StateUnknown || wkr.state == StateBooting {
505                 label, threshold = "new ", wkr.wp.timeoutBooting
506         }
507         if dur < threshold {
508                 return false
509         }
510         wkr.logger.WithFields(logrus.Fields{
511                 "Duration": dur,
512                 "Since":    wkr.probed,
513                 "State":    wkr.state,
514         }).Warnf("%sinstance unresponsive, shutting down", label)
515         wkr.shutdown()
516         return true
517 }
518
519 // Returns true if the instance is eligible for shutdown: either it's
520 // been idle too long, or idleBehavior=Drain and nothing is running.
521 //
522 // caller must have lock.
523 func (wkr *worker) eligibleForShutdown() bool {
524         if wkr.idleBehavior == IdleBehaviorHold {
525                 return false
526         }
527         draining := wkr.idleBehavior == IdleBehaviorDrain
528         switch wkr.state {
529         case StateBooting:
530                 return draining
531         case StateIdle:
532                 return draining || time.Since(wkr.busy) >= wkr.wp.timeoutIdle
533         case StateRunning:
534                 if !draining {
535                         return false
536                 }
537                 for _, rr := range wkr.running {
538                         if !rr.givenup {
539                                 return false
540                         }
541                 }
542                 for _, rr := range wkr.starting {
543                         if !rr.givenup {
544                                 return false
545                         }
546                 }
547                 // draining, and all remaining runners are just trying
548                 // to force-kill their crunch-run procs
549                 return true
550         default:
551                 return false
552         }
553 }
554
555 // caller must have lock.
556 func (wkr *worker) shutdownIfIdle() bool {
557         if !wkr.eligibleForShutdown() {
558                 return false
559         }
560         wkr.logger.WithFields(logrus.Fields{
561                 "State":        wkr.state,
562                 "IdleDuration": stats.Duration(time.Since(wkr.busy)),
563                 "IdleBehavior": wkr.idleBehavior,
564         }).Info("shutdown worker")
565         wkr.reportBootOutcome(BootOutcomeAborted)
566         wkr.shutdown()
567         return true
568 }
569
570 // caller must have lock.
571 func (wkr *worker) shutdown() {
572         now := time.Now()
573         wkr.updated = now
574         wkr.destroyed = now
575         wkr.state = StateShutdown
576         go wkr.wp.notify()
577         go func() {
578                 err := wkr.instance.Destroy()
579                 if err != nil {
580                         wkr.logger.WithError(err).Warn("shutdown failed")
581                         return
582                 }
583         }()
584 }
585
586 // Save worker tags to cloud provider metadata, if they don't already
587 // match. Caller must have lock.
588 func (wkr *worker) saveTags() {
589         instance := wkr.instance
590         tags := instance.Tags()
591         update := cloud.InstanceTags{
592                 wkr.wp.tagKeyPrefix + tagKeyInstanceType: wkr.instType.Name,
593                 wkr.wp.tagKeyPrefix + tagKeyIdleBehavior: string(wkr.idleBehavior),
594         }
595         save := false
596         for k, v := range update {
597                 if tags[k] != v {
598                         tags[k] = v
599                         save = true
600                 }
601         }
602         if save {
603                 go func() {
604                         err := instance.SetTags(tags)
605                         if err != nil {
606                                 wkr.wp.logger.WithField("Instance", instance.ID()).WithError(err).Warnf("error updating tags")
607                         }
608                 }()
609         }
610 }
611
612 func (wkr *worker) Close() {
613         // This might take time, so do it after unlocking mtx.
614         defer wkr.executor.Close()
615
616         wkr.mtx.Lock()
617         defer wkr.mtx.Unlock()
618         for uuid, rr := range wkr.running {
619                 wkr.logger.WithField("ContainerUUID", uuid).Info("crunch-run process abandoned")
620                 rr.Close()
621         }
622         for uuid, rr := range wkr.starting {
623                 wkr.logger.WithField("ContainerUUID", uuid).Info("crunch-run process abandoned")
624                 rr.Close()
625         }
626 }
627
628 // Add/remove entries in wkr.running to match ctrUUIDs returned by a
629 // probe. Returns true if anything was added or removed.
630 //
631 // Caller must have lock.
632 func (wkr *worker) updateRunning(ctrUUIDs []string) (changed bool) {
633         alive := map[string]bool{}
634         for _, uuid := range ctrUUIDs {
635                 alive[uuid] = true
636                 if _, ok := wkr.running[uuid]; ok {
637                         // unchanged
638                 } else if rr, ok := wkr.starting[uuid]; ok {
639                         wkr.running[uuid] = rr
640                         delete(wkr.starting, uuid)
641                         changed = true
642                 } else {
643                         // We didn't start it -- it must have been
644                         // started by a previous dispatcher process.
645                         wkr.logger.WithField("ContainerUUID", uuid).Info("crunch-run process detected")
646                         wkr.running[uuid] = newRemoteRunner(uuid, wkr)
647                         changed = true
648                 }
649         }
650         for uuid := range wkr.running {
651                 if !alive[uuid] {
652                         wkr.closeRunner(uuid)
653                         changed = true
654                 }
655         }
656         return
657 }
658
659 // caller must have lock.
660 func (wkr *worker) closeRunner(uuid string) {
661         rr := wkr.running[uuid]
662         if rr == nil {
663                 return
664         }
665         wkr.logger.WithField("ContainerUUID", uuid).Info("crunch-run process ended")
666         delete(wkr.running, uuid)
667         rr.Close()
668
669         now := time.Now()
670         wkr.updated = now
671         wkr.wp.exited[uuid] = now
672         if wkr.state == StateRunning && len(wkr.running)+len(wkr.starting) == 0 {
673                 wkr.state = StateIdle
674         }
675 }