13959: Use logrus for crunch-dispatch-local logging.
[arvados.git] / services / crunch-dispatch-slurm / crunch-dispatch-slurm.go
1 // Copyright (C) The Arvados Authors. All rights reserved.
2 //
3 // SPDX-License-Identifier: AGPL-3.0
4
5 package main
6
7 // Dispatcher service for Crunch that submits containers to the slurm queue.
8
9 import (
10         "bytes"
11         "context"
12         "flag"
13         "fmt"
14         "log"
15         "math"
16         "os"
17         "regexp"
18         "strings"
19         "time"
20
21         "git.curoverse.com/arvados.git/lib/dispatchcloud"
22         "git.curoverse.com/arvados.git/sdk/go/arvados"
23         "git.curoverse.com/arvados.git/sdk/go/arvadosclient"
24         "git.curoverse.com/arvados.git/sdk/go/config"
25         "git.curoverse.com/arvados.git/sdk/go/dispatch"
26         "github.com/Sirupsen/logrus"
27         "github.com/coreos/go-systemd/daemon"
28 )
29
30 type logger interface {
31         dispatch.Logger
32         Fatalf(string, ...interface{})
33 }
34
35 const initialNiceValue int64 = 10000
36
37 var (
38         version           = "dev"
39         defaultConfigPath = "/etc/arvados/crunch-dispatch-slurm/crunch-dispatch-slurm.yml"
40 )
41
42 type Dispatcher struct {
43         *dispatch.Dispatcher
44         logger  logrus.FieldLogger
45         cluster *arvados.Cluster
46         sqCheck *SqueueChecker
47         slurm   Slurm
48
49         Client arvados.Client
50
51         SbatchArguments []string
52         PollPeriod      arvados.Duration
53         PrioritySpread  int64
54
55         // crunch-run command to invoke. The container UUID will be
56         // appended. If nil, []string{"crunch-run"} will be used.
57         //
58         // Example: []string{"crunch-run", "--cgroup-parent-subsystem=memory"}
59         CrunchRunCommand []string
60
61         // Extra RAM to reserve (in Bytes) for SLURM job, in addition
62         // to the amount specified in the container's RuntimeConstraints
63         ReserveExtraRAM int64
64
65         // Minimum time between two attempts to run the same container
66         MinRetryPeriod arvados.Duration
67 }
68
69 func main() {
70         logger := logrus.StandardLogger()
71         if os.Getenv("DEBUG") != "" {
72                 logger.SetLevel(logrus.DebugLevel)
73         }
74         logger.Formatter = &logrus.JSONFormatter{
75                 TimestampFormat: "2006-01-02T15:04:05.000000000Z07:00",
76         }
77         disp := &Dispatcher{logger: logger}
78         err := disp.Run(os.Args[0], os.Args[1:])
79         if err != nil {
80                 logrus.Fatalf("%s", err)
81         }
82 }
83
84 func (disp *Dispatcher) Run(prog string, args []string) error {
85         if err := disp.configure(prog, args); err != nil {
86                 return err
87         }
88         disp.setup()
89         return disp.run()
90 }
91
92 // configure() loads config files. Tests skip this.
93 func (disp *Dispatcher) configure(prog string, args []string) error {
94         flags := flag.NewFlagSet(prog, flag.ExitOnError)
95         flags.Usage = func() { usage(flags) }
96
97         configPath := flags.String(
98                 "config",
99                 defaultConfigPath,
100                 "`path` to JSON or YAML configuration file")
101         dumpConfig := flag.Bool(
102                 "dump-config",
103                 false,
104                 "write current configuration to stdout and exit")
105         getVersion := flags.Bool(
106                 "version",
107                 false,
108                 "Print version information and exit.")
109         // Parse args; omit the first arg which is the command name
110         flags.Parse(args)
111
112         // Print version information if requested
113         if *getVersion {
114                 fmt.Printf("crunch-dispatch-slurm %s\n", version)
115                 return nil
116         }
117
118         disp.logger.Printf("crunch-dispatch-slurm %s started", version)
119
120         err := disp.readConfig(*configPath)
121         if err != nil {
122                 return err
123         }
124
125         if disp.CrunchRunCommand == nil {
126                 disp.CrunchRunCommand = []string{"crunch-run"}
127         }
128
129         if disp.PollPeriod == 0 {
130                 disp.PollPeriod = arvados.Duration(10 * time.Second)
131         }
132
133         if disp.Client.APIHost != "" || disp.Client.AuthToken != "" {
134                 // Copy real configs into env vars so [a]
135                 // MakeArvadosClient() uses them, and [b] they get
136                 // propagated to crunch-run via SLURM.
137                 os.Setenv("ARVADOS_API_HOST", disp.Client.APIHost)
138                 os.Setenv("ARVADOS_API_TOKEN", disp.Client.AuthToken)
139                 os.Setenv("ARVADOS_API_HOST_INSECURE", "")
140                 if disp.Client.Insecure {
141                         os.Setenv("ARVADOS_API_HOST_INSECURE", "1")
142                 }
143                 os.Setenv("ARVADOS_KEEP_SERVICES", strings.Join(disp.Client.KeepServiceURIs, " "))
144                 os.Setenv("ARVADOS_EXTERNAL_CLIENT", "")
145         } else {
146                 disp.logger.Warnf("Client credentials missing from config, so falling back on environment variables (deprecated).")
147         }
148
149         if *dumpConfig {
150                 return config.DumpAndExit(disp)
151         }
152
153         siteConfig, err := arvados.GetConfig(arvados.DefaultConfigFile)
154         if os.IsNotExist(err) {
155                 disp.logger.Warnf("no cluster config (%s), proceeding with no node types defined", err)
156         } else if err != nil {
157                 return fmt.Errorf("error loading config: %s", err)
158         } else if disp.cluster, err = siteConfig.GetCluster(""); err != nil {
159                 return fmt.Errorf("config error: %s", err)
160         }
161
162         return nil
163 }
164
165 // setup() initializes private fields after configure().
166 func (disp *Dispatcher) setup() {
167         if disp.logger == nil {
168                 disp.logger = logrus.StandardLogger()
169         }
170         arv, err := arvadosclient.MakeArvadosClient()
171         if err != nil {
172                 disp.logger.Fatalf("Error making Arvados client: %v", err)
173         }
174         arv.Retries = 25
175
176         disp.slurm = &slurmCLI{}
177         disp.sqCheck = &SqueueChecker{
178                 Logger:         disp.logger,
179                 Period:         time.Duration(disp.PollPeriod),
180                 PrioritySpread: disp.PrioritySpread,
181                 Slurm:          disp.slurm,
182         }
183         disp.Dispatcher = &dispatch.Dispatcher{
184                 Arv:            arv,
185                 Logger:         disp.logger,
186                 RunContainer:   disp.runContainer,
187                 PollPeriod:     time.Duration(disp.PollPeriod),
188                 MinRetryPeriod: time.Duration(disp.MinRetryPeriod),
189         }
190 }
191
192 func (disp *Dispatcher) run() error {
193         defer disp.sqCheck.Stop()
194
195         if disp.cluster != nil && len(disp.cluster.InstanceTypes) > 0 {
196                 go dispatchcloud.SlurmNodeTypeFeatureKludge(disp.cluster)
197         }
198
199         if _, err := daemon.SdNotify(false, "READY=1"); err != nil {
200                 log.Printf("Error notifying init daemon: %v", err)
201         }
202         go disp.checkSqueueForOrphans()
203         return disp.Dispatcher.Run(context.Background())
204 }
205
206 var containerUuidPattern = regexp.MustCompile(`^[a-z0-9]{5}-dz642-[a-z0-9]{15}$`)
207
208 // Check the next squeue report, and invoke TrackContainer for all the
209 // containers in the report. This gives us a chance to cancel slurm
210 // jobs started by a previous dispatch process that never released
211 // their slurm allocations even though their container states are
212 // Cancelled or Complete. See https://dev.arvados.org/issues/10979
213 func (disp *Dispatcher) checkSqueueForOrphans() {
214         for _, uuid := range disp.sqCheck.All() {
215                 if !containerUuidPattern.MatchString(uuid) {
216                         continue
217                 }
218                 err := disp.TrackContainer(uuid)
219                 if err != nil {
220                         log.Printf("checkSqueueForOrphans: TrackContainer(%s): %s", uuid, err)
221                 }
222         }
223 }
224
225 func (disp *Dispatcher) slurmConstraintArgs(container arvados.Container) []string {
226         mem := int64(math.Ceil(float64(container.RuntimeConstraints.RAM+container.RuntimeConstraints.KeepCacheRAM+disp.ReserveExtraRAM) / float64(1048576)))
227
228         var disk int64
229         for _, m := range container.Mounts {
230                 if m.Kind == "tmp" {
231                         disk += m.Capacity
232                 }
233         }
234         disk = int64(math.Ceil(float64(disk) / float64(1048576)))
235         return []string{
236                 fmt.Sprintf("--mem=%d", mem),
237                 fmt.Sprintf("--cpus-per-task=%d", container.RuntimeConstraints.VCPUs),
238                 fmt.Sprintf("--tmp=%d", disk),
239         }
240 }
241
242 func (disp *Dispatcher) sbatchArgs(container arvados.Container) ([]string, error) {
243         var args []string
244         args = append(args, disp.SbatchArguments...)
245         args = append(args, "--job-name="+container.UUID, fmt.Sprintf("--nice=%d", initialNiceValue))
246
247         if disp.cluster == nil {
248                 // no instance types configured
249                 args = append(args, disp.slurmConstraintArgs(container)...)
250         } else if it, err := dispatchcloud.ChooseInstanceType(disp.cluster, &container); err == dispatchcloud.ErrInstanceTypesNotConfigured {
251                 // ditto
252                 args = append(args, disp.slurmConstraintArgs(container)...)
253         } else if err != nil {
254                 return nil, err
255         } else {
256                 // use instancetype constraint instead of slurm mem/cpu/tmp specs
257                 args = append(args, "--constraint=instancetype="+it.Name)
258         }
259
260         if len(container.SchedulingParameters.Partitions) > 0 {
261                 args = append(args, "--partition="+strings.Join(container.SchedulingParameters.Partitions, ","))
262         }
263
264         return args, nil
265 }
266
267 func (disp *Dispatcher) submit(container arvados.Container, crunchRunCommand []string) error {
268         // append() here avoids modifying crunchRunCommand's
269         // underlying array, which is shared with other goroutines.
270         crArgs := append([]string(nil), crunchRunCommand...)
271         crArgs = append(crArgs, container.UUID)
272         crScript := strings.NewReader(execScript(crArgs))
273
274         sbArgs, err := disp.sbatchArgs(container)
275         if err != nil {
276                 return err
277         }
278         log.Printf("running sbatch %+q", sbArgs)
279         return disp.slurm.Batch(crScript, sbArgs)
280 }
281
282 // Submit a container to the slurm queue (or resume monitoring if it's
283 // already in the queue).  Cancel the slurm job if the container's
284 // priority changes to zero or its state indicates it's no longer
285 // running.
286 func (disp *Dispatcher) runContainer(_ *dispatch.Dispatcher, ctr arvados.Container, status <-chan arvados.Container) {
287         ctx, cancel := context.WithCancel(context.Background())
288         defer cancel()
289
290         if ctr.State == dispatch.Locked && !disp.sqCheck.HasUUID(ctr.UUID) {
291                 log.Printf("Submitting container %s to slurm", ctr.UUID)
292                 if err := disp.submit(ctr, disp.CrunchRunCommand); err != nil {
293                         var text string
294                         if err, ok := err.(dispatchcloud.ConstraintsNotSatisfiableError); ok {
295                                 var logBuf bytes.Buffer
296                                 fmt.Fprintf(&logBuf, "cannot run container %s: %s\n", ctr.UUID, err)
297                                 if len(err.AvailableTypes) == 0 {
298                                         fmt.Fprint(&logBuf, "No instance types are configured.\n")
299                                 } else {
300                                         fmt.Fprint(&logBuf, "Available instance types:\n")
301                                         for _, t := range err.AvailableTypes {
302                                                 fmt.Fprintf(&logBuf,
303                                                         "Type %q: %d VCPUs, %d RAM, %d Scratch, %f Price\n",
304                                                         t.Name, t.VCPUs, t.RAM, t.Scratch, t.Price,
305                                                 )
306                                         }
307                                 }
308                                 text = logBuf.String()
309                                 disp.UpdateState(ctr.UUID, dispatch.Cancelled)
310                         } else {
311                                 text = fmt.Sprintf("Error submitting container %s to slurm: %s", ctr.UUID, err)
312                         }
313                         log.Print(text)
314
315                         lr := arvadosclient.Dict{"log": arvadosclient.Dict{
316                                 "object_uuid": ctr.UUID,
317                                 "event_type":  "dispatch",
318                                 "properties":  map[string]string{"text": text}}}
319                         disp.Arv.Create("logs", lr, nil)
320
321                         disp.Unlock(ctr.UUID)
322                         return
323                 }
324         }
325
326         log.Printf("Start monitoring container %v in state %q", ctr.UUID, ctr.State)
327         defer log.Printf("Done monitoring container %s", ctr.UUID)
328
329         // If the container disappears from the slurm queue, there is
330         // no point in waiting for further dispatch updates: just
331         // clean up and return.
332         go func(uuid string) {
333                 for ctx.Err() == nil && disp.sqCheck.HasUUID(uuid) {
334                 }
335                 cancel()
336         }(ctr.UUID)
337
338         for {
339                 select {
340                 case <-ctx.Done():
341                         // Disappeared from squeue
342                         if err := disp.Arv.Get("containers", ctr.UUID, nil, &ctr); err != nil {
343                                 log.Printf("error getting final container state for %s: %s", ctr.UUID, err)
344                         }
345                         switch ctr.State {
346                         case dispatch.Running:
347                                 disp.UpdateState(ctr.UUID, dispatch.Cancelled)
348                         case dispatch.Locked:
349                                 disp.Unlock(ctr.UUID)
350                         }
351                         return
352                 case updated, ok := <-status:
353                         if !ok {
354                                 log.Printf("container %s is done: cancel slurm job", ctr.UUID)
355                                 disp.scancel(ctr)
356                         } else if updated.Priority == 0 {
357                                 log.Printf("container %s has state %q, priority %d: cancel slurm job", ctr.UUID, updated.State, updated.Priority)
358                                 disp.scancel(ctr)
359                         } else {
360                                 p := int64(updated.Priority)
361                                 if p <= 1000 {
362                                         // API is providing
363                                         // user-assigned priority. If
364                                         // ctrs have equal priority,
365                                         // run the older one first.
366                                         p = int64(p)<<50 - (updated.CreatedAt.UnixNano() >> 14)
367                                 }
368                                 disp.sqCheck.SetPriority(ctr.UUID, p)
369                         }
370                 }
371         }
372 }
373 func (disp *Dispatcher) scancel(ctr arvados.Container) {
374         err := disp.slurm.Cancel(ctr.UUID)
375         if err != nil {
376                 log.Printf("scancel: %s", err)
377                 time.Sleep(time.Second)
378         } else if disp.sqCheck.HasUUID(ctr.UUID) {
379                 log.Printf("container %s is still in squeue after scancel", ctr.UUID)
380                 time.Sleep(time.Second)
381         }
382 }
383
384 func (disp *Dispatcher) readConfig(path string) error {
385         err := config.LoadFile(disp, path)
386         if err != nil && os.IsNotExist(err) && path == defaultConfigPath {
387                 log.Printf("Config not specified. Continue with default configuration.")
388                 err = nil
389         }
390         return err
391 }