Merge branch 'master' into 10786-remove-centos6-from-build-directory
[arvados.git] / services / api / lib / crunch_dispatch.rb
1 require 'open3'
2 require 'shellwords'
3
4 class CrunchDispatch
5   extend DbCurrentTime
6   include ApplicationHelper
7   include Process
8
9   EXIT_TEMPFAIL = 75
10   EXIT_RETRY_UNLOCKED = 93
11   RETRY_UNLOCKED_LIMIT = 3
12
13   class LogTime < Time
14     def to_s
15       self.utc.strftime "%Y-%m-%d_%H:%M:%S"
16     end
17   end
18
19   def initialize
20     @crunch_job_bin = (ENV['CRUNCH_JOB_BIN'] || `which arv-crunch-job`.strip)
21     if @crunch_job_bin.empty?
22       raise "No CRUNCH_JOB_BIN env var, and crunch-job not in path."
23     end
24
25     @docker_bin = ENV['CRUNCH_JOB_DOCKER_BIN']
26     @docker_run_args = ENV['CRUNCH_JOB_DOCKER_RUN_ARGS']
27     @cgroup_root = ENV['CRUNCH_CGROUP_ROOT']
28
29     @arvados_internal = Rails.configuration.git_internal_dir
30     if not File.exist? @arvados_internal
31       $stderr.puts `mkdir -p #{@arvados_internal.shellescape} && git init --bare #{@arvados_internal.shellescape}`
32       raise "No internal git repository available" unless ($? == 0)
33     end
34
35     @repo_root = Rails.configuration.git_repositories_dir
36     @arvados_repo_path = Repository.where(name: "arvados").first.server_path
37     @authorizations = {}
38     @did_recently = {}
39     @fetched_commits = {}
40     @git_tags = {}
41     @node_state = {}
42     @pipe_auth_tokens = {}
43     @running = {}
44     @todo = []
45     @todo_job_retries = {}
46     @job_retry_counts = Hash.new(0)
47     @todo_pipelines = []
48   end
49
50   def sysuser
51     return act_as_system_user
52   end
53
54   def refresh_todo
55     if @runoptions[:jobs]
56       @todo = @todo_job_retries.values + Job.queue.select(&:repository)
57     end
58     if @runoptions[:pipelines]
59       @todo_pipelines = PipelineInstance.queue
60     end
61   end
62
63   def each_slurm_line(cmd, outfmt, max_fields=nil)
64     max_fields ||= outfmt.split(":").size
65     max_fields += 1  # To accommodate the node field we add
66     @@slurm_version ||= Gem::Version.new(`sinfo --version`.match(/\b[\d\.]+\b/)[0])
67     if Gem::Version.new('2.3') <= @@slurm_version
68       `#{cmd} --noheader -o '%n:#{outfmt}'`.each_line do |line|
69         yield line.chomp.split(":", max_fields)
70       end
71     else
72       # Expand rows with hostname ranges (like "foo[1-3,5,9-12]:idle")
73       # into multiple rows with one hostname each.
74       `#{cmd} --noheader -o '%N:#{outfmt}'`.each_line do |line|
75         tokens = line.chomp.split(":", max_fields)
76         if (re = tokens[0].match(/^(.*?)\[([-,\d]+)\]$/))
77           tokens.shift
78           re[2].split(",").each do |range|
79             range = range.split("-").collect(&:to_i)
80             (range[0]..range[-1]).each do |n|
81               yield [re[1] + n.to_s] + tokens
82             end
83           end
84         else
85           yield tokens
86         end
87       end
88     end
89   end
90
91   def slurm_status
92     slurm_nodes = {}
93     each_slurm_line("sinfo", "%t") do |hostname, state|
94       # Treat nodes in idle* state as down, because the * means that slurm
95       # hasn't been able to communicate with it recently.
96       state.sub!(/^idle\*/, "down")
97       state.sub!(/\W+$/, "")
98       state = "down" unless %w(idle alloc down).include?(state)
99       slurm_nodes[hostname] = {state: state, job: nil}
100     end
101     each_slurm_line("squeue", "%j") do |hostname, job_uuid|
102       slurm_nodes[hostname][:job] = job_uuid if slurm_nodes[hostname]
103     end
104     slurm_nodes
105   end
106
107   def update_node_status
108     return unless Server::Application.config.crunch_job_wrapper.to_s.match(/^slurm/)
109     slurm_status.each_pair do |hostname, slurmdata|
110       next if @node_state[hostname] == slurmdata
111       begin
112         node = Node.where('hostname=?', hostname).order(:last_ping_at).last
113         if node
114           $stderr.puts "dispatch: update #{hostname} state to #{slurmdata}"
115           node.info["slurm_state"] = slurmdata[:state]
116           node.job_uuid = slurmdata[:job]
117           if node.save
118             @node_state[hostname] = slurmdata
119           else
120             $stderr.puts "dispatch: failed to update #{node.uuid}: #{node.errors.messages}"
121           end
122         elsif slurmdata[:state] != 'down'
123           $stderr.puts "dispatch: SLURM reports '#{hostname}' is not down, but no node has that name"
124         end
125       rescue => error
126         $stderr.puts "dispatch: error updating #{hostname} node status: #{error}"
127       end
128     end
129   end
130
131   def positive_int(raw_value, default=nil)
132     value = begin raw_value.to_i rescue 0 end
133     if value > 0
134       value
135     else
136       default
137     end
138   end
139
140   NODE_CONSTRAINT_MAP = {
141     # Map Job runtime_constraints keys to the corresponding Node info key.
142     'min_ram_mb_per_node' => 'total_ram_mb',
143     'min_scratch_mb_per_node' => 'total_scratch_mb',
144     'min_cores_per_node' => 'total_cpu_cores',
145   }
146
147   def nodes_available_for_job_now(job)
148     # Find Nodes that satisfy a Job's runtime constraints (by building
149     # a list of Procs and using them to test each Node).  If there
150     # enough to run the Job, return an array of their names.
151     # Otherwise, return nil.
152     need_procs = NODE_CONSTRAINT_MAP.each_pair.map do |job_key, node_key|
153       Proc.new do |node|
154         positive_int(node.properties[node_key], 0) >=
155           positive_int(job.runtime_constraints[job_key], 0)
156       end
157     end
158     min_node_count = positive_int(job.runtime_constraints['min_nodes'], 1)
159     usable_nodes = []
160     Node.all.select do |node|
161       node.info['slurm_state'] == 'idle'
162     end.sort_by do |node|
163       # Prefer nodes with no price, then cheap nodes, then expensive nodes
164       node.properties['cloud_node']['price'].to_f rescue 0
165     end.each do |node|
166       if need_procs.select { |need_proc| not need_proc.call(node) }.any?
167         # At least one runtime constraint is not satisfied by this node
168         next
169       end
170       usable_nodes << node
171       if usable_nodes.count >= min_node_count
172         return usable_nodes.map { |n| n.hostname }
173       end
174     end
175     nil
176   end
177
178   def nodes_available_for_job(job)
179     # Check if there are enough idle nodes with the Job's minimum
180     # hardware requirements to run it.  If so, return an array of
181     # their names.  If not, up to once per hour, signal start_jobs to
182     # hold off launching Jobs.  This delay is meant to give the Node
183     # Manager an opportunity to make new resources available for new
184     # Jobs.
185     #
186     # The exact timing parameters here might need to be adjusted for
187     # the best balance between helping the longest-waiting Jobs run,
188     # and making efficient use of immediately available resources.
189     # These are all just first efforts until we have more data to work
190     # with.
191     nodelist = nodes_available_for_job_now(job)
192     if nodelist.nil? and not did_recently(:wait_for_available_nodes, 3600)
193       $stderr.puts "dispatch: waiting for nodes for #{job.uuid}"
194       @node_wait_deadline = Time.now + 5.minutes
195     end
196     nodelist
197   end
198
199   def fail_job job, message, skip_lock: false
200     $stderr.puts "dispatch: #{job.uuid}: #{message}"
201     begin
202       Log.new(object_uuid: job.uuid,
203               event_type: 'dispatch',
204               owner_uuid: job.owner_uuid,
205               summary: message,
206               properties: {"text" => message}).save!
207     rescue
208       $stderr.puts "dispatch: log.create failed"
209     end
210
211     if not skip_lock and not have_job_lock?(job)
212       begin
213         job.lock @authorizations[job.uuid].user.uuid
214       rescue ArvadosModel::AlreadyLockedError
215         $stderr.puts "dispatch: tried to mark job #{job.uuid} as failed but it was already locked by someone else"
216         return
217       end
218     end
219
220     job.state = "Failed"
221     if not job.save
222       $stderr.puts "dispatch: save failed setting job #{job.uuid} to failed"
223     end
224   end
225
226   def stdout_s(cmd_a, opts={})
227     IO.popen(cmd_a, "r", opts) do |pipe|
228       return pipe.read.chomp
229     end
230   end
231
232   def git_cmd(*cmd_a)
233     ["git", "--git-dir=#{@arvados_internal}"] + cmd_a
234   end
235
236   def get_authorization(job)
237     if @authorizations[job.uuid] and
238         @authorizations[job.uuid].user.uuid != job.modified_by_user_uuid
239       # We already made a token for this job, but we need a new one
240       # because modified_by_user_uuid has changed (the job will run
241       # as a different user).
242       @authorizations[job.uuid].update_attributes expires_at: Time.now
243       @authorizations[job.uuid] = nil
244     end
245     if not @authorizations[job.uuid]
246       auth = ApiClientAuthorization.
247         new(user: User.where('uuid=?', job.modified_by_user_uuid).first,
248             api_client_id: 0)
249       if not auth.save
250         $stderr.puts "dispatch: auth.save failed for #{job.uuid}"
251       else
252         @authorizations[job.uuid] = auth
253       end
254     end
255     @authorizations[job.uuid]
256   end
257
258   def internal_repo_has_commit? sha1
259     if (not @fetched_commits[sha1] and
260         sha1 == stdout_s(git_cmd("rev-list", "-n1", sha1), err: "/dev/null") and
261         $? == 0)
262       @fetched_commits[sha1] = true
263     end
264     return @fetched_commits[sha1]
265   end
266
267   def get_commit src_repo, sha1
268     return true if internal_repo_has_commit? sha1
269
270     # commit does not exist in internal repository, so import the
271     # source repository using git fetch-pack
272     cmd = git_cmd("fetch-pack", "--no-progress", "--all", src_repo)
273     $stderr.puts "dispatch: #{cmd}"
274     $stderr.puts(stdout_s(cmd))
275     @fetched_commits[sha1] = ($? == 0)
276   end
277
278   def tag_commit(commit_hash, tag_name)
279     # @git_tags[T]==V if we know commit V has been tagged T in the
280     # arvados_internal repository.
281     if not @git_tags[tag_name]
282       cmd = git_cmd("tag", tag_name, commit_hash)
283       $stderr.puts "dispatch: #{cmd}"
284       $stderr.puts(stdout_s(cmd, err: "/dev/null"))
285       unless $? == 0
286         # git tag failed.  This may be because the tag already exists, so check for that.
287         tag_rev = stdout_s(git_cmd("rev-list", "-n1", tag_name))
288         if $? == 0
289           # We got a revision back
290           if tag_rev != commit_hash
291             # Uh oh, the tag doesn't point to the revision we were expecting.
292             # Someone has been monkeying with the job record and/or git.
293             fail_job job, "Existing tag #{tag_name} points to commit #{tag_rev} but expected commit #{commit_hash}"
294             return nil
295           end
296           # we're okay (fall through to setting @git_tags below)
297         else
298           # git rev-list failed for some reason.
299           fail_job job, "'git tag' for #{tag_name} failed but did not find any existing tag using 'git rev-list'"
300           return nil
301         end
302       end
303       # 'git tag' was successful, or there is an existing tag that points to the same revision.
304       @git_tags[tag_name] = commit_hash
305     elsif @git_tags[tag_name] != commit_hash
306       fail_job job, "Existing tag #{tag_name} points to commit #{@git_tags[tag_name]} but this job uses commit #{commit_hash}"
307       return nil
308     end
309     @git_tags[tag_name]
310   end
311
312   def start_jobs
313     @todo.each do |job|
314       next if @running[job.uuid]
315
316       cmd_args = nil
317       case Server::Application.config.crunch_job_wrapper
318       when :none
319         if @running.size > 0
320             # Don't run more than one at a time.
321             return
322         end
323         cmd_args = []
324       when :slurm_immediate
325         nodelist = nodes_available_for_job(job)
326         if nodelist.nil?
327           if Time.now < @node_wait_deadline
328             break
329           else
330             next
331           end
332         end
333         cmd_args = ["salloc",
334                     "--chdir=/",
335                     "--immediate",
336                     "--exclusive",
337                     "--no-kill",
338                     "--job-name=#{job.uuid}",
339                     "--nodelist=#{nodelist.join(',')}"]
340       else
341         raise "Unknown crunch_job_wrapper: #{Server::Application.config.crunch_job_wrapper}"
342       end
343
344       cmd_args = sudo_preface + cmd_args
345
346       next unless get_authorization job
347
348       ready = internal_repo_has_commit? job.script_version
349
350       if not ready
351         # Import the commit from the specified repository into the
352         # internal repository. This should have been done already when
353         # the job was created/updated; this code is obsolete except to
354         # avoid deployment races. Failing the job would be a
355         # reasonable thing to do at this point.
356         repo = Repository.where(name: job.repository).first
357         if repo.nil? or repo.server_path.nil?
358           fail_job job, "Repository #{job.repository} not found under #{@repo_root}"
359           next
360         end
361         ready &&= get_commit repo.server_path, job.script_version
362         ready &&= tag_commit job.script_version, job.uuid
363       end
364
365       # This should be unnecessary, because API server does it during
366       # job create/update, but it's still not a bad idea to verify the
367       # tag is correct before starting the job:
368       ready &&= tag_commit job.script_version, job.uuid
369
370       # The arvados_sdk_version doesn't support use of arbitrary
371       # remote URLs, so the requested version isn't necessarily copied
372       # into the internal repository yet.
373       if job.arvados_sdk_version
374         ready &&= get_commit @arvados_repo_path, job.arvados_sdk_version
375         ready &&= tag_commit job.arvados_sdk_version, "#{job.uuid}-arvados-sdk"
376       end
377
378       if not ready
379         fail_job job, "commit not present in internal repository"
380         next
381       end
382
383       cmd_args += [@crunch_job_bin,
384                    '--job-api-token', @authorizations[job.uuid].api_token,
385                    '--job', job.uuid,
386                    '--git-dir', @arvados_internal]
387
388       if @cgroup_root
389         cmd_args += ['--cgroup-root', @cgroup_root]
390       end
391
392       if @docker_bin
393         cmd_args += ['--docker-bin', @docker_bin]
394       end
395
396       if @docker_run_args
397         cmd_args += ['--docker-run-args', @docker_run_args]
398       end
399
400       if have_job_lock?(job)
401         cmd_args << "--force-unlock"
402       end
403
404       $stderr.puts "dispatch: #{cmd_args.join ' '}"
405
406       begin
407         i, o, e, t = Open3.popen3(*cmd_args)
408       rescue
409         $stderr.puts "dispatch: popen3: #{$!}"
410         sleep 1
411         next
412       end
413
414       $stderr.puts "dispatch: job #{job.uuid}"
415       start_banner = "dispatch: child #{t.pid} start #{LogTime.now}"
416       $stderr.puts start_banner
417
418       @running[job.uuid] = {
419         stdin: i,
420         stdout: o,
421         stderr: e,
422         wait_thr: t,
423         job: job,
424         buf: {stderr: '', stdout: ''},
425         started: false,
426         sent_int: 0,
427         job_auth: @authorizations[job.uuid],
428         stderr_buf_to_flush: '',
429         stderr_flushed_at: Time.new(0),
430         bytes_logged: 0,
431         events_logged: 0,
432         log_throttle_is_open: true,
433         log_throttle_reset_time: Time.now + Rails.configuration.crunch_log_throttle_period,
434         log_throttle_bytes_so_far: 0,
435         log_throttle_lines_so_far: 0,
436         log_throttle_bytes_skipped: 0,
437         log_throttle_partial_line_last_at: Time.new(0),
438         log_throttle_first_partial_line: true,
439       }
440       i.close
441       @todo_job_retries.delete(job.uuid)
442       update_node_status
443     end
444   end
445
446   # Test for hard cap on total output and for log throttling.  Returns whether
447   # the log line should go to output or not.  Modifies "line" in place to
448   # replace it with an error if a logging limit is tripped.
449   def rate_limit running_job, line
450     message = false
451     linesize = line.size
452     if running_job[:log_throttle_is_open]
453       partial_line = false
454       skip_counts = false
455       matches = line.match(/^\S+ \S+ \d+ \d+ stderr (.*)/)
456       if matches and matches[1] and matches[1].start_with?('[...]') and matches[1].end_with?('[...]')
457         partial_line = true
458         if Time.now > running_job[:log_throttle_partial_line_last_at] + Rails.configuration.crunch_log_partial_line_throttle_period
459           running_job[:log_throttle_partial_line_last_at] = Time.now
460         else
461           skip_counts = true
462         end
463       end
464
465       if !skip_counts
466         running_job[:log_throttle_lines_so_far] += 1
467         running_job[:log_throttle_bytes_so_far] += linesize
468         running_job[:bytes_logged] += linesize
469       end
470
471       if (running_job[:bytes_logged] >
472           Rails.configuration.crunch_limit_log_bytes_per_job)
473         message = "Exceeded log limit #{Rails.configuration.crunch_limit_log_bytes_per_job} bytes (crunch_limit_log_bytes_per_job). Log will be truncated."
474         running_job[:log_throttle_reset_time] = Time.now + 100.years
475         running_job[:log_throttle_is_open] = false
476
477       elsif (running_job[:log_throttle_bytes_so_far] >
478              Rails.configuration.crunch_log_throttle_bytes)
479         remaining_time = running_job[:log_throttle_reset_time] - Time.now
480         message = "Exceeded rate #{Rails.configuration.crunch_log_throttle_bytes} bytes per #{Rails.configuration.crunch_log_throttle_period} seconds (crunch_log_throttle_bytes). Logging will be silenced for the next #{remaining_time.round} seconds."
481         running_job[:log_throttle_is_open] = false
482
483       elsif (running_job[:log_throttle_lines_so_far] >
484              Rails.configuration.crunch_log_throttle_lines)
485         remaining_time = running_job[:log_throttle_reset_time] - Time.now
486         message = "Exceeded rate #{Rails.configuration.crunch_log_throttle_lines} lines per #{Rails.configuration.crunch_log_throttle_period} seconds (crunch_log_throttle_lines), logging will be silenced for the next #{remaining_time.round} seconds."
487         running_job[:log_throttle_is_open] = false
488
489       elsif partial_line and running_job[:log_throttle_first_partial_line]
490         running_job[:log_throttle_first_partial_line] = false
491         message = "Rate-limiting partial segments of long lines to one every #{Rails.configuration.crunch_log_partial_line_throttle_period} seconds."
492       end
493     end
494
495     if not running_job[:log_throttle_is_open]
496       # Don't log anything if any limit has been exceeded. Just count lossage.
497       running_job[:log_throttle_bytes_skipped] += linesize
498     end
499
500     if message
501       # Yes, write to logs, but use our "rate exceeded" message
502       # instead of the log message that exceeded the limit.
503       message += " A complete log is still being written to Keep, and will be available when the job finishes.\n"
504       line.replace message
505       true
506     elsif partial_line
507       false
508     else
509       running_job[:log_throttle_is_open]
510     end
511   end
512
513   def read_pipes
514     @running.each do |job_uuid, j|
515       now = Time.now
516       if now > j[:log_throttle_reset_time]
517         # It has been more than throttle_period seconds since the last
518         # checkpoint so reset the throttle
519         if j[:log_throttle_bytes_skipped] > 0
520           message = "#{job_uuid} ! Skipped #{j[:log_throttle_bytes_skipped]} bytes of log"
521           $stderr.puts message
522           j[:stderr_buf_to_flush] << "#{LogTime.now} #{message}\n"
523         end
524
525         j[:log_throttle_reset_time] = now + Rails.configuration.crunch_log_throttle_period
526         j[:log_throttle_bytes_so_far] = 0
527         j[:log_throttle_lines_so_far] = 0
528         j[:log_throttle_bytes_skipped] = 0
529         j[:log_throttle_is_open] = true
530         j[:log_throttle_partial_line_last_at] = Time.new(0)
531         j[:log_throttle_first_partial_line] = true
532       end
533
534       j[:buf].each do |stream, streambuf|
535         # Read some data from the child stream
536         buf = ''
537         begin
538           # It's important to use a big enough buffer here. When we're
539           # being flooded with logs, we must read and discard many
540           # bytes at once. Otherwise, we can easily peg a CPU with
541           # time-checking and other loop overhead. (Quick tests show a
542           # 1MiB buffer working 2.5x as fast as a 64 KiB buffer.)
543           #
544           # So don't reduce this buffer size!
545           buf = j[stream].read_nonblock(2**20)
546         rescue Errno::EAGAIN, EOFError
547         end
548
549         # Short circuit the counting code if we're just going to throw
550         # away the data anyway.
551         if not j[:log_throttle_is_open]
552           j[:log_throttle_bytes_skipped] += streambuf.size + buf.size
553           streambuf.replace ''
554           next
555         elsif buf == ''
556           next
557         end
558
559         # Append to incomplete line from previous read, if any
560         streambuf << buf
561
562         bufend = ''
563         streambuf.each_line do |line|
564           if not line.end_with? $/
565             if line.size > Rails.configuration.crunch_log_throttle_bytes
566               # Without a limit here, we'll use 2x an arbitrary amount
567               # of memory, and waste a lot of time copying strings
568               # around, all without providing any feedback to anyone
569               # about what's going on _or_ hitting any of our throttle
570               # limits.
571               #
572               # Here we leave "line" alone, knowing it will never be
573               # sent anywhere: rate_limit() will reach
574               # crunch_log_throttle_bytes immediately. However, we'll
575               # leave [...] in bufend: if the trailing end of the long
576               # line does end up getting sent anywhere, it will have
577               # some indication that it is incomplete.
578               bufend = "[...]"
579             else
580               # If line length is sane, we'll wait for the rest of the
581               # line to appear in the next read_pipes() call.
582               bufend = line
583               break
584             end
585           end
586           # rate_limit returns true or false as to whether to actually log
587           # the line or not.  It also modifies "line" in place to replace
588           # it with an error if a logging limit is tripped.
589           if rate_limit j, line
590             $stderr.print "#{job_uuid} ! " unless line.index(job_uuid)
591             $stderr.puts line
592             pub_msg = "#{LogTime.now} #{line.strip}\n"
593             j[:stderr_buf_to_flush] << pub_msg
594           end
595         end
596
597         # Leave the trailing incomplete line (if any) in streambuf for
598         # next time.
599         streambuf.replace bufend
600       end
601       # Flush buffered logs to the logs table, if appropriate. We have
602       # to do this even if we didn't collect any new logs this time:
603       # otherwise, buffered data older than seconds_between_events
604       # won't get flushed until new data arrives.
605       write_log j
606     end
607   end
608
609   def reap_children
610     return if 0 == @running.size
611     pid_done = nil
612     j_done = nil
613
614     if false
615       begin
616         pid_done = waitpid(-1, Process::WNOHANG | Process::WUNTRACED)
617         if pid_done
618           j_done = @running.values.
619             select { |j| j[:wait_thr].pid == pid_done }.
620             first
621         end
622       rescue SystemCallError
623         # I have @running processes but system reports I have no
624         # children. This is likely to happen repeatedly if it happens at
625         # all; I will log this no more than once per child process I
626         # start.
627         if 0 < @running.select { |uuid,j| j[:warned_waitpid_error].nil? }.size
628           children = @running.values.collect { |j| j[:wait_thr].pid }.join ' '
629           $stderr.puts "dispatch: IPC bug: waitpid() error (#{$!}), but I have children #{children}"
630         end
631         @running.each do |uuid,j| j[:warned_waitpid_error] = true end
632       end
633     else
634       @running.each do |uuid, j|
635         if j[:wait_thr].status == false
636           pid_done = j[:wait_thr].pid
637           j_done = j
638         end
639       end
640     end
641
642     return if !pid_done
643
644     job_done = j_done[:job]
645
646     # Ensure every last drop of stdout and stderr is consumed.
647     read_pipes
648     # Reset flush timestamp to make sure log gets written.
649     j_done[:stderr_flushed_at] = Time.new(0)
650     # Write any remaining logs.
651     write_log j_done
652
653     j_done[:buf].each do |stream, streambuf|
654       if streambuf != ''
655         $stderr.puts streambuf + "\n"
656       end
657     end
658
659     # Wait the thread (returns a Process::Status)
660     exit_status = j_done[:wait_thr].value.exitstatus
661     exit_tempfail = exit_status == EXIT_TEMPFAIL
662
663     $stderr.puts "dispatch: child #{pid_done} exit #{exit_status}"
664     $stderr.puts "dispatch: job #{job_done.uuid} end"
665
666     jobrecord = Job.find_by_uuid(job_done.uuid)
667
668     if exit_status == EXIT_RETRY_UNLOCKED or (exit_tempfail and @job_retry_counts.include? jobrecord.uuid)
669       # Only this crunch-dispatch process can retry the job:
670       # it's already locked, and there's no way to put it back in the
671       # Queued state.  Put it in our internal todo list unless the job
672       # has failed this way excessively.
673       @job_retry_counts[jobrecord.uuid] += 1
674       exit_tempfail = @job_retry_counts[jobrecord.uuid] <= RETRY_UNLOCKED_LIMIT
675       if exit_tempfail
676         @todo_job_retries[jobrecord.uuid] = jobrecord
677       else
678         $stderr.puts("dispatch: job #{jobrecord.uuid} exceeded node failure retry limit -- giving up")
679       end
680     end
681
682     if !exit_tempfail
683       @job_retry_counts.delete(jobrecord.uuid)
684       if jobrecord.state == "Running"
685         # Apparently there was an unhandled error.  That could potentially
686         # include "all allocated nodes failed" when we don't to retry
687         # because the job has already been retried RETRY_UNLOCKED_LIMIT
688         # times.  Fail the job.
689         jobrecord.state = "Failed"
690         if not jobrecord.save
691           $stderr.puts "dispatch: jobrecord.save failed"
692         end
693       end
694     else
695       # If the job failed to run due to an infrastructure
696       # issue with crunch-job or slurm, we want the job to stay in the
697       # queue. If crunch-job exited after losing a race to another
698       # crunch-job process, it exits 75 and we should leave the job
699       # record alone so the winner of the race can do its thing.
700       # If crunch-job exited after all of its allocated nodes failed,
701       # it exits 93, and we want to retry it later (see the
702       # EXIT_RETRY_UNLOCKED `if` block).
703       #
704       # There is still an unhandled race condition: If our crunch-job
705       # process is about to lose a race with another crunch-job
706       # process, but crashes before getting to its "exit 75" (for
707       # example, "cannot fork" or "cannot reach API server") then we
708       # will assume incorrectly that it's our process's fault
709       # jobrecord.started_at is non-nil, and mark the job as failed
710       # even though the winner of the race is probably still doing
711       # fine.
712     end
713
714     # Invalidate the per-job auth token, unless the job is still queued and we
715     # might want to try it again.
716     if jobrecord.state != "Queued" and !@todo_job_retries.include?(jobrecord.uuid)
717       j_done[:job_auth].update_attributes expires_at: Time.now
718     end
719
720     @running.delete job_done.uuid
721   end
722
723   def update_pipelines
724     expire_tokens = @pipe_auth_tokens.dup
725     @todo_pipelines.each do |p|
726       pipe_auth = (@pipe_auth_tokens[p.uuid] ||= ApiClientAuthorization.
727                    create(user: User.where('uuid=?', p.modified_by_user_uuid).first,
728                           api_client_id: 0))
729       puts `export ARVADOS_API_TOKEN=#{pipe_auth.api_token} && arv-run-pipeline-instance --run-pipeline-here --no-wait --instance #{p.uuid}`
730       expire_tokens.delete p.uuid
731     end
732
733     expire_tokens.each do |k, v|
734       v.update_attributes expires_at: Time.now
735       @pipe_auth_tokens.delete k
736     end
737   end
738
739   def parse_argv argv
740     @runoptions = {}
741     (argv.any? ? argv : ['--jobs', '--pipelines']).each do |arg|
742       case arg
743       when '--jobs'
744         @runoptions[:jobs] = true
745       when '--pipelines'
746         @runoptions[:pipelines] = true
747       else
748         abort "Unrecognized command line option '#{arg}'"
749       end
750     end
751     if not (@runoptions[:jobs] or @runoptions[:pipelines])
752       abort "Nothing to do. Please specify at least one of: --jobs, --pipelines."
753     end
754   end
755
756   def run argv
757     parse_argv argv
758
759     # We want files written by crunch-dispatch to be writable by other
760     # processes with the same GID, see bug #7228
761     File.umask(0002)
762
763     # This is how crunch-job child procs know where the "refresh"
764     # trigger file is
765     ENV["CRUNCH_REFRESH_TRIGGER"] = Rails.configuration.crunch_refresh_trigger
766
767     # If salloc can't allocate resources immediately, make it use our
768     # temporary failure exit code.  This ensures crunch-dispatch won't
769     # mark a job failed because of an issue with node allocation.
770     # This often happens when another dispatcher wins the race to
771     # allocate nodes.
772     ENV["SLURM_EXIT_IMMEDIATE"] = CrunchDispatch::EXIT_TEMPFAIL.to_s
773
774     if ENV["CRUNCH_DISPATCH_LOCKFILE"]
775       lockfilename = ENV.delete "CRUNCH_DISPATCH_LOCKFILE"
776       lockfile = File.open(lockfilename, File::RDWR|File::CREAT, 0644)
777       unless lockfile.flock File::LOCK_EX|File::LOCK_NB
778         abort "Lock unavailable on #{lockfilename} - exit"
779       end
780     end
781
782     @signal = {}
783     %w{TERM INT}.each do |sig|
784       signame = sig
785       Signal.trap(sig) do
786         $stderr.puts "Received #{signame} signal"
787         @signal[:term] = true
788       end
789     end
790
791     act_as_system_user
792     User.first.group_permissions
793     $stderr.puts "dispatch: ready"
794     while !@signal[:term] or @running.size > 0
795       read_pipes
796       if @signal[:term]
797         @running.each do |uuid, j|
798           if !j[:started] and j[:sent_int] < 2
799             begin
800               Process.kill 'INT', j[:wait_thr].pid
801             rescue Errno::ESRCH
802               # No such pid = race condition + desired result is
803               # already achieved
804             end
805             j[:sent_int] += 1
806           end
807         end
808       else
809         refresh_todo unless did_recently(:refresh_todo, 1.0)
810         update_node_status unless did_recently(:update_node_status, 1.0)
811         unless @todo.empty? or did_recently(:start_jobs, 1.0) or @signal[:term]
812           start_jobs
813         end
814         unless (@todo_pipelines.empty? and @pipe_auth_tokens.empty?) or did_recently(:update_pipelines, 5.0)
815           update_pipelines
816         end
817       end
818       reap_children
819       select(@running.values.collect { |j| [j[:stdout], j[:stderr]] }.flatten,
820              [], [], 1)
821     end
822     # If there are jobs we wanted to retry, we have to mark them as failed now.
823     # Other dispatchers can't pick them up because we hold their lock.
824     @todo_job_retries.each_key do |job_uuid|
825       job = Job.find_by_uuid(job_uuid)
826       if job.state == "Running"
827         fail_job(job, "crunch-dispatch was stopped during job's tempfail retry loop")
828       end
829     end
830   end
831
832   def fail_jobs before: nil
833     act_as_system_user do
834       threshold = nil
835       if before == 'reboot'
836         boottime = nil
837         open('/proc/stat').map(&:split).each do |stat, t|
838           if stat == 'btime'
839             boottime = t
840           end
841         end
842         if not boottime
843           raise "Could not find btime in /proc/stat"
844         end
845         threshold = Time.at(boottime.to_i)
846       elsif before
847         threshold = Time.parse(before, Time.now)
848       else
849         threshold = db_current_time
850       end
851       Rails.logger.info "fail_jobs: threshold is #{threshold}"
852
853       if Rails.configuration.crunch_job_wrapper == :slurm_immediate
854         # [["slurm_job_id", "slurm_job_name"], ...]
855         squeue = File.popen(['squeue', '-h', '-o', '%i %j']).readlines.map do |line|
856           line.strip.split(' ', 2)
857         end
858       else
859         squeue = []
860       end
861
862       Job.where('state = ? and started_at < ?', Job::Running, threshold).
863         each do |job|
864         Rails.logger.debug "fail_jobs: #{job.uuid} started #{job.started_at}"
865         squeue.each do |slurm_id, slurm_name|
866           if slurm_name == job.uuid
867             Rails.logger.info "fail_jobs: scancel #{slurm_id} for #{job.uuid}"
868             scancel slurm_id
869           end
870         end
871         fail_job(job, "cleaned up stale job: started before #{threshold}",
872                  skip_lock: true)
873       end
874     end
875   end
876
877   protected
878
879   def have_job_lock?(job)
880     # Return true if the given job is locked by this crunch-dispatch, normally
881     # because we've run crunch-job for it.
882     @todo_job_retries.include?(job.uuid)
883   end
884
885   def did_recently(thing, min_interval)
886     if !@did_recently[thing] or @did_recently[thing] < Time.now - min_interval
887       @did_recently[thing] = Time.now
888       false
889     else
890       true
891     end
892   end
893
894   # send message to log table. we want these records to be transient
895   def write_log running_job
896     return if running_job[:stderr_buf_to_flush] == ''
897
898     # Send out to log event if buffer size exceeds the bytes per event or if
899     # it has been at least crunch_log_seconds_between_events seconds since
900     # the last flush.
901     if running_job[:stderr_buf_to_flush].size > Rails.configuration.crunch_log_bytes_per_event or
902         (Time.now - running_job[:stderr_flushed_at]) >= Rails.configuration.crunch_log_seconds_between_events
903       begin
904         log = Log.new(object_uuid: running_job[:job].uuid,
905                       event_type: 'stderr',
906                       owner_uuid: running_job[:job].owner_uuid,
907                       properties: {"text" => running_job[:stderr_buf_to_flush]})
908         log.save!
909         running_job[:events_logged] += 1
910       rescue => exception
911         $stderr.puts "Failed to write logs"
912         $stderr.puts exception.backtrace
913       end
914       running_job[:stderr_buf_to_flush] = ''
915       running_job[:stderr_flushed_at] = Time.now
916     end
917   end
918
919   def scancel slurm_id
920     cmd = sudo_preface + ['scancel', slurm_id]
921     puts File.popen(cmd).read
922     if not $?.success?
923       Rails.logger.error "scancel #{slurm_id.shellescape}: $?"
924     end
925   end
926
927   def sudo_preface
928     return [] if not Server::Application.config.crunch_job_user
929     ["sudo", "-E", "-u",
930      Server::Application.config.crunch_job_user,
931      "LD_LIBRARY_PATH=#{ENV['LD_LIBRARY_PATH']}",
932      "PATH=#{ENV['PATH']}",
933      "PERLLIB=#{ENV['PERLLIB']}",
934      "PYTHONPATH=#{ENV['PYTHONPATH']}",
935      "RUBYLIB=#{ENV['RUBYLIB']}",
936      "GEM_PATH=#{ENV['GEM_PATH']}"]
937   end
938 end