7 (ARGV.any? ? ARGV : ['--jobs', '--pipelines']).each do |arg|
10 $options[:jobs] = true
12 $options[:pipelines] = true
14 abort "Unrecognized command line option '#{arg}'"
17 if not ($options[:jobs] or $options[:pipelines])
18 abort "Nothing to do. Please specify at least one of: --jobs, --pipelines."
21 ARGV.reject! { |a| a =~ /--jobs|--pipelines/ }
25 %w{TERM INT}.each do |sig|
28 $stderr.puts "Received #{signame} signal"
33 if ENV["CRUNCH_DISPATCH_LOCKFILE"]
34 lockfilename = ENV.delete "CRUNCH_DISPATCH_LOCKFILE"
35 lockfile = File.open(lockfilename, File::RDWR|File::CREAT, 0644)
36 unless lockfile.flock File::LOCK_EX|File::LOCK_NB
37 abort "Lock unavailable on #{lockfilename} - exit"
41 ENV["RAILS_ENV"] = ARGV[0] || ENV["RAILS_ENV"] || "development"
43 require File.dirname(__FILE__) + '/../config/boot'
44 require File.dirname(__FILE__) + '/../config/environment'
48 include ApplicationHelper
51 return act_as_system_user
57 @todo = Job.queue.select(&:repository)
60 if $options[:pipelines]
61 @todo_pipelines = PipelineInstance.queue
65 def each_slurm_line(cmd, outfmt, max_fields=nil)
66 max_fields ||= outfmt.split(":").size
67 max_fields += 1 # To accommodate the node field we add
68 @@slurm_version ||= Gem::Version.new(`sinfo --version`.match(/\b[\d\.]+\b/)[0])
69 if Gem::Version.new('2.3') <= @@slurm_version
70 `#{cmd} --noheader -o '%n:#{outfmt}'`.each_line do |line|
71 yield line.chomp.split(":", max_fields)
74 # Expand rows with hostname ranges (like "foo[1-3,5,9-12]:idle")
75 # into multiple rows with one hostname each.
76 `#{cmd} --noheader -o '%N:#{outfmt}'`.each_line do |line|
77 tokens = line.chomp.split(":", max_fields)
78 if (re = tokens[0].match /^(.*?)\[([-,\d]+)\]$/)
80 re[2].split(",").each do |range|
81 range = range.split("-").collect(&:to_i)
82 (range[0]..range[-1]).each do |n|
83 yield [re[1] + n.to_s] + tokens
95 each_slurm_line("sinfo", "%t") do |hostname, state|
96 # Treat nodes in idle* state as down, because the * means that slurm
97 # hasn't been able to communicate with it recently.
98 state.sub!(/^idle\*/, "down")
99 state.sub!(/\W+$/, "")
100 state = "down" unless %w(idle alloc down).include?(state)
101 slurm_nodes[hostname] = {state: state, job: nil}
103 each_slurm_line("squeue", "%j") do |hostname, job_uuid|
104 slurm_nodes[hostname][:job] = job_uuid if slurm_nodes[hostname]
109 def update_node_status
110 return unless Server::Application.config.crunch_job_wrapper.to_s.match /^slurm/
112 slurm_status.each_pair do |hostname, slurmdata|
113 next if @node_state[hostname] == slurmdata
115 node = Node.where('hostname=?', hostname).order(:last_ping_at).last
117 $stderr.puts "dispatch: update #{hostname} state to #{slurmdata}"
118 node.info["slurm_state"] = slurmdata[:state]
119 node.job_uuid = slurmdata[:job]
121 @node_state[hostname] = slurmdata
123 $stderr.puts "dispatch: failed to update #{node.uuid}: #{node.errors.messages}"
125 elsif slurmdata[:state] != 'down'
126 $stderr.puts "dispatch: SLURM reports '#{hostname}' is not down, but no node has that name"
129 $stderr.puts "dispatch: error updating #{hostname} node status: #{error}"
134 def positive_int(raw_value, default=nil)
135 value = begin raw_value.to_i rescue 0 end
143 NODE_CONSTRAINT_MAP = {
144 # Map Job runtime_constraints keys to the corresponding Node info key.
145 'min_ram_mb_per_node' => 'total_ram_mb',
146 'min_scratch_mb_per_node' => 'total_scratch_mb',
147 'min_cores_per_node' => 'total_cpu_cores',
150 def nodes_available_for_job_now(job)
151 # Find Nodes that satisfy a Job's runtime constraints (by building
152 # a list of Procs and using them to test each Node). If there
153 # enough to run the Job, return an array of their names.
154 # Otherwise, return nil.
155 need_procs = NODE_CONSTRAINT_MAP.each_pair.map do |job_key, node_key|
157 positive_int(node.info[node_key], 0) >=
158 positive_int(job.runtime_constraints[job_key], 0)
161 min_node_count = positive_int(job.runtime_constraints['min_nodes'], 1)
163 Node.find_each do |node|
164 good_node = (node.info['slurm_state'] == 'idle')
165 need_procs.each { |node_test| good_node &&= node_test.call(node) }
168 if usable_nodes.count >= min_node_count
169 return usable_nodes.map { |node| node.hostname }
176 def nodes_available_for_job(job)
177 # Check if there are enough idle nodes with the Job's minimum
178 # hardware requirements to run it. If so, return an array of
179 # their names. If not, up to once per hour, signal start_jobs to
180 # hold off launching Jobs. This delay is meant to give the Node
181 # Manager an opportunity to make new resources available for new
184 # The exact timing parameters here might need to be adjusted for
185 # the best balance between helping the longest-waiting Jobs run,
186 # and making efficient use of immediately available resources.
187 # These are all just first efforts until we have more data to work
189 nodelist = nodes_available_for_job_now(job)
190 if nodelist.nil? and not did_recently(:wait_for_available_nodes, 3600)
191 $stderr.puts "dispatch: waiting for nodes for #{job.uuid}"
192 @node_wait_deadline = Time.now + 5.minutes
197 def fail_job job, message
198 $stderr.puts "dispatch: #{job.uuid}: #{message}"
200 Log.new(object_uuid: job.uuid,
201 event_type: 'dispatch',
202 owner_uuid: job.owner_uuid,
204 properties: {"text" => message}).save!
206 $stderr.puts "dispatch: log.create failed"
210 job.lock @authorizations[job.uuid].user.uuid
213 $stderr.puts "dispatch: save failed setting job #{job.uuid} to failed"
215 rescue ArvadosModel::AlreadyLockedError
216 $stderr.puts "dispatch: tried to mark job #{job.uuid} as failed but it was already locked by someone else"
222 next if @running[job.uuid]
225 case Server::Application.config.crunch_job_wrapper
228 # Don't run more than one at a time.
232 when :slurm_immediate
233 nodelist = nodes_available_for_job(job)
235 if Time.now < @node_wait_deadline
241 cmd_args = ["salloc",
246 "--job-name=#{job.uuid}",
247 "--nodelist=#{nodelist.join(',')}"]
249 raise "Unknown crunch_job_wrapper: #{Server::Application.config.crunch_job_wrapper}"
252 if Server::Application.config.crunch_job_user
253 cmd_args.unshift("sudo", "-E", "-u",
254 Server::Application.config.crunch_job_user,
255 "PATH=#{ENV['PATH']}",
256 "PERLLIB=#{ENV['PERLLIB']}",
257 "PYTHONPATH=#{ENV['PYTHONPATH']}",
258 "RUBYLIB=#{ENV['RUBYLIB']}",
259 "GEM_PATH=#{ENV['GEM_PATH']}")
262 @authorizations ||= {}
263 if @authorizations[job.uuid] and
264 @authorizations[job.uuid].user.uuid != job.modified_by_user_uuid
265 # We already made a token for this job, but we need a new one
266 # because modified_by_user_uuid has changed (the job will run
267 # as a different user).
268 @authorizations[job.uuid].update_attributes expires_at: Time.now
269 @authorizations[job.uuid] = nil
271 if not @authorizations[job.uuid]
272 auth = ApiClientAuthorization.
273 new(user: User.where('uuid=?', job.modified_by_user_uuid).first,
276 $stderr.puts "dispatch: auth.save failed"
279 @authorizations[job.uuid] = auth
282 crunch_job_bin = (ENV['CRUNCH_JOB_BIN'] || `which arv-crunch-job`.strip)
283 if crunch_job_bin == ''
284 raise "No CRUNCH_JOB_BIN env var, and crunch-job not in path."
287 arvados_internal = Rails.configuration.git_internal_dir
288 if not File.exists? arvados_internal
289 $stderr.puts `mkdir -p #{arvados_internal.shellescape} && cd #{arvados_internal.shellescape} && git init --bare`
292 git = "git --git-dir=#{arvados_internal.shellescape}"
294 # @fetched_commits[V]==true if we know commit V exists in the
295 # arvados_internal git repository.
296 @fetched_commits ||= {}
297 if !@fetched_commits[job.script_version]
299 repo_root = Rails.configuration.git_repositories_dir
300 src_repo = File.join(repo_root, job.repository + '.git')
301 if not File.exists? src_repo
302 src_repo = File.join(repo_root, job.repository, '.git')
303 if not File.exists? src_repo
304 fail_job job, "No #{job.repository}.git or #{job.repository}/.git at #{repo_root}"
309 # check if the commit needs to be fetched or not
310 commit_rev = `#{git} rev-list -n1 #{job.script_version.shellescape} 2>/dev/null`.chomp
311 unless $? == 0 and commit_rev == job.script_version
312 # commit does not exist in internal repository, so import the source repository using git fetch-pack
313 cmd = "#{git} fetch-pack --no-progress --all #{src_repo.shellescape}"
314 $stderr.puts "dispatch: #{cmd}"
315 $stderr.puts `#{cmd}`
317 fail_job job, "git fetch-pack failed"
321 @fetched_commits[job.script_version] = true
324 # @job_tags[J]==V if we know commit V has been tagged J in the
325 # arvados_internal repository. (J is a job UUID, V is a commit
328 if not @job_tags[job.uuid]
329 cmd = "#{git} tag #{job.uuid.shellescape} #{job.script_version.shellescape} 2>/dev/null"
330 $stderr.puts "dispatch: #{cmd}"
331 $stderr.puts `#{cmd}`
333 # git tag failed. This may be because the tag already exists, so check for that.
334 tag_rev = `#{git} rev-list -n1 #{job.uuid.shellescape}`.chomp
336 # We got a revision back
337 if tag_rev != job.script_version
338 # Uh oh, the tag doesn't point to the revision we were expecting.
339 # Someone has been monkeying with the job record and/or git.
340 fail_job job, "Existing tag #{job.uuid} points to commit #{tag_rev} but expected commit #{job.script_version}"
343 # we're okay (fall through to setting @job_tags below)
345 # git rev-list failed for some reason.
346 fail_job job, "'git tag' for #{job.uuid} failed but did not find any existing tag using 'git rev-list'"
350 # 'git tag' was successful, or there is an existing tag that points to the same revision.
351 @job_tags[job.uuid] = job.script_version
352 elsif @job_tags[job.uuid] != job.script_version
353 fail_job job, "Existing tag #{job.uuid} points to commit #{@job_tags[job.uuid]} but this job uses commit #{job.script_version}"
357 cmd_args << crunch_job_bin
358 cmd_args << '--job-api-token'
359 cmd_args << @authorizations[job.uuid].api_token
362 cmd_args << '--git-dir'
363 cmd_args << arvados_internal
365 $stderr.puts "dispatch: #{cmd_args.join ' '}"
368 i, o, e, t = Open3.popen3(*cmd_args)
370 $stderr.puts "dispatch: popen3: #{$!}"
375 $stderr.puts "dispatch: job #{job.uuid}"
376 start_banner = "dispatch: child #{t.pid} start #{Time.now.ctime.to_s}"
377 $stderr.puts start_banner
379 @running[job.uuid] = {
385 buf: {stderr: '', stdout: ''},
388 job_auth: @authorizations[job.uuid],
389 stderr_buf_to_flush: '',
390 stderr_flushed_at: Time.new(0),
393 log_throttle_is_open: true,
394 log_throttle_reset_time: Time.now + Rails.configuration.crunch_log_throttle_period,
395 log_throttle_bytes_so_far: 0,
396 log_throttle_lines_so_far: 0,
397 log_throttle_bytes_skipped: 0,
404 # Test for hard cap on total output and for log throttling. Returns whether
405 # the log line should go to output or not. Modifies "line" in place to
406 # replace it with an error if a logging limit is tripped.
407 def rate_limit running_job, line
410 if running_job[:log_throttle_is_open]
411 running_job[:log_throttle_lines_so_far] += 1
412 running_job[:log_throttle_bytes_so_far] += linesize
413 running_job[:bytes_logged] += linesize
415 if (running_job[:bytes_logged] >
416 Rails.configuration.crunch_limit_log_bytes_per_job)
417 message = "Exceeded log limit #{Rails.configuration.crunch_limit_log_bytes_per_job} bytes (crunch_limit_log_bytes_per_job). Log will be truncated."
418 running_job[:log_throttle_reset_time] = Time.now + 100.years
419 running_job[:log_throttle_is_open] = false
421 elsif (running_job[:log_throttle_bytes_so_far] >
422 Rails.configuration.crunch_log_throttle_bytes)
423 remaining_time = running_job[:log_throttle_reset_time] - Time.now
424 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.\n"
425 running_job[:log_throttle_is_open] = false
427 elsif (running_job[:log_throttle_lines_so_far] >
428 Rails.configuration.crunch_log_throttle_lines)
429 remaining_time = running_job[:log_throttle_reset_time] - Time.now
430 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.\n"
431 running_job[:log_throttle_is_open] = false
435 if not running_job[:log_throttle_is_open]
436 # Don't log anything if any limit has been exceeded. Just count lossage.
437 running_job[:log_throttle_bytes_skipped] += linesize
441 # Yes, write to logs, but use our "rate exceeded" message
442 # instead of the log message that exceeded the limit.
446 running_job[:log_throttle_is_open]
451 @running.each do |job_uuid, j|
455 if now > j[:log_throttle_reset_time]
456 # It has been more than throttle_period seconds since the last
457 # checkpoint so reset the throttle
458 if j[:log_throttle_bytes_skipped] > 0
459 message = "#{job_uuid} ! Skipped #{j[:log_throttle_bytes_skipped]} bytes of log"
461 j[:stderr_buf_to_flush] << "#{Time.now.ctime.to_s} #{message}\n"
464 j[:log_throttle_reset_time] = now + Rails.configuration.crunch_log_throttle_period
465 j[:log_throttle_bytes_so_far] = 0
466 j[:log_throttle_lines_so_far] = 0
467 j[:log_throttle_bytes_skipped] = 0
468 j[:log_throttle_is_open] = true
471 j[:buf].each do |stream, streambuf|
472 # Read some data from the child stream
475 # It's important to use a big enough buffer here. When we're
476 # being flooded with logs, we must read and discard many
477 # bytes at once. Otherwise, we can easily peg a CPU with
478 # time-checking and other loop overhead. (Quick tests show a
479 # 1MiB buffer working 2.5x as fast as a 64 KiB buffer.)
481 # So don't reduce this buffer size!
482 buf = j[stream].read_nonblock(2**20)
483 rescue Errno::EAGAIN, EOFError
486 # Short circuit the counting code if we're just going to throw
487 # away the data anyway.
488 if not j[:log_throttle_is_open]
489 j[:log_throttle_bytes_skipped] += streambuf.size + buf.size
496 # Append to incomplete line from previous read, if any
500 streambuf.each_line do |line|
501 if not line.end_with? $/
502 if line.size > Rails.configuration.crunch_log_throttle_bytes
503 # Without a limit here, we'll use 2x an arbitrary amount
504 # of memory, and waste a lot of time copying strings
505 # around, all without providing any feedback to anyone
506 # about what's going on _or_ hitting any of our throttle
509 # Here we leave "line" alone, knowing it will never be
510 # sent anywhere: rate_limit() will reach
511 # crunch_log_throttle_bytes immediately. However, we'll
512 # leave [...] in bufend: if the trailing end of the long
513 # line does end up getting sent anywhere, it will have
514 # some indication that it is incomplete.
517 # If line length is sane, we'll wait for the rest of the
518 # line to appear in the next read_pipes() call.
523 # rate_limit returns true or false as to whether to actually log
524 # the line or not. It also modifies "line" in place to replace
525 # it with an error if a logging limit is tripped.
526 if rate_limit j, line
527 $stderr.print "#{job_uuid} ! " unless line.index(job_uuid)
529 pub_msg = "#{Time.now.ctime.to_s} #{line.strip}\n"
530 j[:stderr_buf_to_flush] << pub_msg
534 # Leave the trailing incomplete line (if any) in streambuf for
536 streambuf.replace bufend
538 # Flush buffered logs to the logs table, if appropriate. We have
539 # to do this even if we didn't collect any new logs this time:
540 # otherwise, buffered data older than seconds_between_events
541 # won't get flushed until new data arrives.
547 return if 0 == @running.size
553 pid_done = waitpid(-1, Process::WNOHANG | Process::WUNTRACED)
555 j_done = @running.values.
556 select { |j| j[:wait_thr].pid == pid_done }.
559 rescue SystemCallError
560 # I have @running processes but system reports I have no
561 # children. This is likely to happen repeatedly if it happens at
562 # all; I will log this no more than once per child process I
564 if 0 < @running.select { |uuid,j| j[:warned_waitpid_error].nil? }.size
565 children = @running.values.collect { |j| j[:wait_thr].pid }.join ' '
566 $stderr.puts "dispatch: IPC bug: waitpid() error (#{$!}), but I have children #{children}"
568 @running.each do |uuid,j| j[:warned_waitpid_error] = true end
571 @running.each do |uuid, j|
572 if j[:wait_thr].status == false
573 pid_done = j[:wait_thr].pid
581 job_done = j_done[:job]
582 $stderr.puts "dispatch: child #{pid_done} exit"
583 $stderr.puts "dispatch: job #{job_done.uuid} end"
585 # Ensure every last drop of stdout and stderr is consumed.
587 # Reset flush timestamp to make sure log gets written.
588 j_done[:stderr_flushed_at] = Time.new(0)
589 # Write any remaining logs.
592 j_done[:buf].each do |stream, streambuf|
594 $stderr.puts streambuf + "\n"
598 # Wait the thread (returns a Process::Status)
599 exit_status = j_done[:wait_thr].value.exitstatus
601 jobrecord = Job.find_by_uuid(job_done.uuid)
602 if exit_status != 75 and jobrecord.state == "Running"
603 # crunch-job did not return exit code 75 (see below) and left the job in
604 # the "Running" state, which means there was an unhandled error. Fail
606 jobrecord.state = "Failed"
607 if not jobrecord.save
608 $stderr.puts "dispatch: jobrecord.save failed"
611 # Don't fail the job if crunch-job didn't even get as far as
612 # starting it. If the job failed to run due to an infrastructure
613 # issue with crunch-job or slurm, we want the job to stay in the
614 # queue. If crunch-job exited after losing a race to another
615 # crunch-job process, it exits 75 and we should leave the job
616 # record alone so the winner of the race do its thing.
618 # There is still an unhandled race condition: If our crunch-job
619 # process is about to lose a race with another crunch-job
620 # process, but crashes before getting to its "exit 75" (for
621 # example, "cannot fork" or "cannot reach API server") then we
622 # will assume incorrectly that it's our process's fault
623 # jobrecord.started_at is non-nil, and mark the job as failed
624 # even though the winner of the race is probably still doing
628 # Invalidate the per-job auth token, unless the job is still queued and we
629 # might want to try it again.
630 if jobrecord.state != "Queued"
631 j_done[:job_auth].update_attributes expires_at: Time.now
634 @running.delete job_done.uuid
638 expire_tokens = @pipe_auth_tokens.dup
639 @todo_pipelines.each do |p|
640 pipe_auth = (@pipe_auth_tokens[p.uuid] ||= ApiClientAuthorization.
641 create(user: User.where('uuid=?', p.modified_by_user_uuid).first,
643 puts `export ARVADOS_API_TOKEN=#{pipe_auth.api_token} && arv-run-pipeline-instance --run-pipeline-here --no-wait --instance #{p.uuid}`
644 expire_tokens.delete p.uuid
647 expire_tokens.each do |k, v|
648 v.update_attributes expires_at: Time.now
649 @pipe_auth_tokens.delete k
656 @pipe_auth_tokens ||= { }
657 $stderr.puts "dispatch: ready"
658 while !$signal[:term] or @running.size > 0
661 @running.each do |uuid, j|
662 if !j[:started] and j[:sent_int] < 2
664 Process.kill 'INT', j[:wait_thr].pid
666 # No such pid = race condition + desired result is
673 refresh_todo unless did_recently(:refresh_todo, 1.0)
674 update_node_status unless did_recently(:update_node_status, 1.0)
675 unless @todo.empty? or did_recently(:start_jobs, 1.0) or $signal[:term]
678 unless (@todo_pipelines.empty? and @pipe_auth_tokens.empty?) or did_recently(:update_pipelines, 5.0)
683 select(@running.values.collect { |j| [j[:stdout], j[:stderr]] }.flatten,
690 def did_recently(thing, min_interval)
692 if !@did_recently[thing] or @did_recently[thing] < Time.now - min_interval
693 @did_recently[thing] = Time.now
700 # send message to log table. we want these records to be transient
701 def write_log running_job
702 return if running_job[:stderr_buf_to_flush] == ''
704 # Send out to log event if buffer size exceeds the bytes per event or if
705 # it has been at least crunch_log_seconds_between_events seconds since
707 if running_job[:stderr_buf_to_flush].size > Rails.configuration.crunch_log_bytes_per_event or
708 (Time.now - running_job[:stderr_flushed_at]) >= Rails.configuration.crunch_log_seconds_between_events
710 log = Log.new(object_uuid: running_job[:job].uuid,
711 event_type: 'stderr',
712 owner_uuid: running_job[:job].owner_uuid,
713 properties: {"text" => running_job[:stderr_buf_to_flush]})
715 running_job[:events_logged] += 1
717 $stderr.puts "Failed to write logs"
718 $stderr.puts exception.backtrace
720 running_job[:stderr_buf_to_flush] = ''
721 running_job[:stderr_flushed_at] = Time.now
726 # This is how crunch-job child procs know where the "refresh" trigger file is
727 ENV["CRUNCH_REFRESH_TRIGGER"] = Rails.configuration.crunch_refresh_trigger