services/api/script/crunch-dispatch.rb

   1 #!/usr/bin/env ruby
   2
   3 include Process
   4
   5 $options = {}
   6 (ARGV.any? ? ARGV : ['--jobs', '--pipelines']).each do |arg|
   7   case arg
   8   when '--jobs'
   9     $options[:jobs] = true
  10   when '--pipelines'
  11     $options[:pipelines] = true
  12   else
  13     abort "Unrecognized command line option '#{arg}'"
  14   end
  15 end
  16 if not ($options[:jobs] or $options[:pipelines])
  17   abort "Nothing to do. Please specify at least one of: --jobs, --pipelines."
  18 end
  19
  20 ARGV.reject! { |a| a =~ /--jobs|--pipelines/ }
  21
  22 $warned = {}
  23 $signal = {}
  24 %w{TERM INT}.each do |sig|
  25   signame = sig
  26   Signal.trap(sig) do
  27     $stderr.puts "Received #{signame} signal"
  28     $signal[:term] = true
  29   end
  30 end
  31
  32 if ENV["CRUNCH_DISPATCH_LOCKFILE"]
  33   lockfilename = ENV.delete "CRUNCH_DISPATCH_LOCKFILE"
  34   lockfile = File.open(lockfilename, File::RDWR|File::CREAT, 0644)
  35   unless lockfile.flock File::LOCK_EX|File::LOCK_NB
  36     abort "Lock unavailable on #{lockfilename} - exit"
  37   end
  38 end
  39
  40 ENV["RAILS_ENV"] = ARGV[0] || ENV["RAILS_ENV"] || "development"
  41
  42 require File.dirname(__FILE__) + '/../config/boot'
  43 require File.dirname(__FILE__) + '/../config/environment'
  44 require 'open3'
  45
  46 class Dispatcher
  47   include ApplicationHelper
  48
  49   def sysuser
  50     return act_as_system_user
  51   end
  52
  53   def refresh_todo
  54     @todo = []
  55     if $options[:jobs]
  56       @todo = Job.queue.select(&:repository)
  57     end
  58     @todo_pipelines = []
  59     if $options[:pipelines]
  60       @todo_pipelines = PipelineInstance.queue
  61     end
  62   end
  63
  64   def sinfo
  65     @@slurm_version ||= Gem::Version.new(`sinfo --version`.match(/\b[\d\.]+\b/)[0])
  66     if Gem::Version.new('2.3') <= @@slurm_version
  67       `sinfo --noheader -o '%n:%t'`.strip
  68     else
  69       # Expand rows with hostname ranges (like "foo[1-3,5,9-12]:idle")
  70       # into multiple rows with one hostname each.
  71       `sinfo --noheader -o '%N:%t'`.split("\n").collect do |line|
  72         tokens = line.split ":"
  73         if (re = tokens[0].match /^(.*?)\[([-,\d]+)\]$/)
  74           re[2].split(",").collect do |range|
  75             range = range.split("-").collect(&:to_i)
  76             (range[0]..range[-1]).collect do |n|
  77               [re[1] + n.to_s, tokens[1..-1]].join ":"
  78             end
  79           end
  80         else
  81           tokens.join ":"
  82         end
  83       end.flatten.join "\n"
  84     end
  85   end
  86
  87   def update_node_status
  88     if Server::Application.config.crunch_job_wrapper.to_s.match /^slurm/
  89       @node_state ||= {}
  90       node_seen = {}
  91       begin
  92         sinfo.split("\n").
  93           each do |line|
  94           re = line.match /(\S+?):+(idle|alloc|down)?/
  95           next if !re
  96
  97           _, node_name, node_state = *re
  98           node_state = 'down' unless %w(idle alloc down).include? node_state
  99
 100           # sinfo tells us about a node N times if it is shared by N partitions
 101           next if node_seen[node_name]
 102           node_seen[node_name] = true
 103
 104           # update our database (and cache) when a node's state changes
 105           if @node_state[node_name] != node_state
 106             @node_state[node_name] = node_state
 107             node = Node.where('hostname=?', node_name).order(:last_ping_at).last
 108             if node
 109               $stderr.puts "dispatch: update #{node_name} state to #{node_state}"
 110               node.info['slurm_state'] = node_state
 111               if not node.save
 112                 $stderr.puts "dispatch: failed to update #{node.uuid}: #{node.errors.messages}"
 113               end
 114             elsif node_state != 'down'
 115               $stderr.puts "dispatch: sinfo reports '#{node_name}' is not down, but no node has that name"
 116             end
 117           end
 118         end
 119       rescue => error
 120         $stderr.puts "dispatch: error updating node status: #{error}"
 121       end
 122     end
 123   end
 124
 125   def positive_int(raw_value, default=nil)
 126     value = begin raw_value.to_i rescue 0 end
 127     if value > 0
 128       value
 129     else
 130       default
 131     end
 132   end
 133
 134   NODE_CONSTRAINT_MAP = {
 135     # Map Job runtime_constraints keys to the corresponding Node info key.
 136     'min_ram_mb_per_node' => 'total_ram_mb',
 137     'min_scratch_mb_per_node' => 'total_scratch_mb',
 138     'min_cores_per_node' => 'total_cpu_cores',
 139   }
 140
 141   def nodes_available_for_job_now(job)
 142     # Find Nodes that satisfy a Job's runtime constraints (by building
 143     # a list of Procs and using them to test each Node).  If there
 144     # enough to run the Job, return an array of their names.
 145     # Otherwise, return nil.
 146     need_procs = NODE_CONSTRAINT_MAP.each_pair.map do |job_key, node_key|
 147       Proc.new do |node|
 148         positive_int(node.info[node_key], 0) >=
 149           positive_int(job.runtime_constraints[job_key], 0)
 150       end
 151     end
 152     min_node_count = positive_int(job.runtime_constraints['min_nodes'], 1)
 153     usable_nodes = []
 154     Node.find_each do |node|
 155       good_node = (node.info['slurm_state'] == 'idle')
 156       need_procs.each { |node_test| good_node &&= node_test.call(node) }
 157       if good_node
 158         usable_nodes << node
 159         if usable_nodes.count >= min_node_count
 160           return usable_nodes.map { |node| node.hostname }
 161         end
 162       end
 163     end
 164     nil
 165   end
 166
 167   def nodes_available_for_job(job)
 168     # Check if there are enough idle nodes with the Job's minimum
 169     # hardware requirements to run it.  If so, return an array of
 170     # their names.  If not, up to once per hour, signal start_jobs to
 171     # hold off launching Jobs.  This delay is meant to give the Node
 172     # Manager an opportunity to make new resources available for new
 173     # Jobs.
 174     #
 175     # The exact timing parameters here might need to be adjusted for
 176     # the best balance between helping the longest-waiting Jobs run,
 177     # and making efficient use of immediately available resources.
 178     # These are all just first efforts until we have more data to work
 179     # with.
 180     nodelist = nodes_available_for_job_now(job)
 181     if nodelist.nil? and not did_recently(:wait_for_available_nodes, 3600)
 182       $stderr.puts "dispatch: waiting for nodes for #{job.uuid}"
 183       @node_wait_deadline = Time.now + 5.minutes
 184     end
 185     nodelist
 186   end
 187
 188   def start_jobs
 189     @todo.each do |job|
 190       next if @running[job.uuid]
 191
 192       cmd_args = nil
 193       case Server::Application.config.crunch_job_wrapper
 194       when :none
 195         if @running.size > 0
 196             # Don't run more than one at a time.
 197             return
 198         end
 199         cmd_args = []
 200       when :slurm_immediate
 201         nodelist = nodes_available_for_job(job)
 202         if nodelist.nil?
 203           if Time.now < @node_wait_deadline
 204             break
 205           else
 206             next
 207           end
 208         end
 209         cmd_args = ["salloc",
 210                     "--chdir=/",
 211                     "--immediate",
 212                     "--exclusive",
 213                     "--no-kill",
 214                     "--job-name=#{job.uuid}",
 215                     "--nodelist=#{nodelist.join(',')}"]
 216       else
 217         raise "Unknown crunch_job_wrapper: #{Server::Application.config.crunch_job_wrapper}"
 218       end
 219
 220       next if !take(job)
 221
 222       if Server::Application.config.crunch_job_user
 223         cmd_args.unshift("sudo", "-E", "-u",
 224                          Server::Application.config.crunch_job_user,
 225                          "PATH=#{ENV['PATH']}",
 226                          "PERLLIB=#{ENV['PERLLIB']}",
 227                          "PYTHONPATH=#{ENV['PYTHONPATH']}",
 228                          "RUBYLIB=#{ENV['RUBYLIB']}",
 229                          "GEM_PATH=#{ENV['GEM_PATH']}")
 230       end
 231
 232       job_auth = ApiClientAuthorization.
 233         new(user: User.where('uuid=?', job.modified_by_user_uuid).first,
 234             api_client_id: 0)
 235       job_auth.save
 236
 237       crunch_job_bin = (ENV['CRUNCH_JOB_BIN'] || `which arv-crunch-job`.strip)
 238       if crunch_job_bin == ''
 239         raise "No CRUNCH_JOB_BIN env var, and crunch-job not in path."
 240       end
 241
 242       require 'shellwords'
 243
 244       arvados_internal = Rails.configuration.git_internal_dir
 245       if not File.exists? arvados_internal
 246         $stderr.puts `mkdir -p #{arvados_internal.shellescape} && cd #{arvados_internal.shellescape} && git init --bare`
 247       end
 248
 249       repo_root = Rails.configuration.git_repositories_dir
 250       src_repo = File.join(repo_root, job.repository + '.git')
 251       if not File.exists? src_repo
 252         src_repo = File.join(repo_root, job.repository, '.git')
 253         if not File.exists? src_repo
 254           $stderr.puts "dispatch: No #{job.repository}.git or #{job.repository}/.git at #{repo_root}"
 255           sleep 1
 256           untake job
 257           next
 258         end
 259       end
 260
 261       $stderr.puts `cd #{arvados_internal.shellescape} && git fetch-pack --all #{src_repo.shellescape} && git tag #{job.uuid.shellescape} #{job.script_version.shellescape}`
 262       unless $? == 0
 263         $stderr.puts "dispatch: git fetch-pack && tag failed"
 264         sleep 1
 265         untake job
 266         next
 267       end
 268
 269       cmd_args << crunch_job_bin
 270       cmd_args << '--job-api-token'
 271       cmd_args << job_auth.api_token
 272       cmd_args << '--job'
 273       cmd_args << job.uuid
 274       cmd_args << '--git-dir'
 275       cmd_args << arvados_internal
 276
 277       $stderr.puts "dispatch: #{cmd_args.join ' '}"
 278
 279       begin
 280         i, o, e, t = Open3.popen3(*cmd_args)
 281       rescue
 282         $stderr.puts "dispatch: popen3: #{$!}"
 283         sleep 1
 284         untake(job)
 285         next
 286       end
 287
 288       $stderr.puts "dispatch: job #{job.uuid}"
 289       start_banner = "dispatch: child #{t.pid} start #{Time.now.ctime.to_s}"
 290       $stderr.puts start_banner
 291
 292       @running[job.uuid] = {
 293         stdin: i,
 294         stdout: o,
 295         stderr: e,
 296         wait_thr: t,
 297         job: job,
 298         stderr_buf: '',
 299         started: false,
 300         sent_int: 0,
 301         job_auth: job_auth,
 302         stderr_buf_to_flush: '',
 303         stderr_flushed_at: 0,
 304         bytes_logged: 0,
 305         events_logged: 0,
 306         log_truncated: false
 307       }
 308       i.close
 309       update_node_status
 310     end
 311   end
 312
 313   def take(job)
 314     # no-op -- let crunch-job take care of locking.
 315     true
 316   end
 317
 318   def untake(job)
 319     # no-op -- let crunch-job take care of locking.
 320     true
 321   end
 322
 323   def read_pipes
 324     @running.each do |job_uuid, j|
 325       job = j[:job]
 326
 327       # Throw away child stdout
 328       begin
 329         j[:stdout].read_nonblock(2**20)
 330       rescue Errno::EAGAIN, EOFError
 331       end
 332
 333       # Read whatever is available from child stderr
 334       stderr_buf = false
 335       begin
 336         stderr_buf = j[:stderr].read_nonblock(2**20)
 337       rescue Errno::EAGAIN, EOFError
 338       end
 339
 340       if stderr_buf
 341         j[:stderr_buf] << stderr_buf
 342         if j[:stderr_buf].index "\n"
 343           lines = j[:stderr_buf].lines("\n").to_a
 344           if j[:stderr_buf][-1] == "\n"
 345             j[:stderr_buf] = ''
 346           else
 347             j[:stderr_buf] = lines.pop
 348           end
 349           lines.each do |line|
 350             $stderr.print "#{job_uuid} ! " unless line.index(job_uuid)
 351             $stderr.puts line
 352             pub_msg = "#{Time.now.ctime.to_s} #{line.strip} \n"
 353             if not j[:log_truncated]
 354               j[:stderr_buf_to_flush] << pub_msg
 355             end
 356           end
 357
 358           if not j[:log_truncated]
 359             if (Rails.configuration.crunch_log_bytes_per_event < j[:stderr_buf_to_flush].size or
 360                 (j[:stderr_flushed_at] + Rails.configuration.crunch_log_seconds_between_events < Time.now.to_i))
 361               write_log j
 362             end
 363           end
 364         end
 365       end
 366     end
 367   end
 368
 369   def reap_children
 370     return if 0 == @running.size
 371     pid_done = nil
 372     j_done = nil
 373
 374     if false
 375       begin
 376         pid_done = waitpid(-1, Process::WNOHANG | Process::WUNTRACED)
 377         if pid_done
 378           j_done = @running.values.
 379             select { |j| j[:wait_thr].pid == pid_done }.
 380             first
 381         end
 382       rescue SystemCallError
 383         # I have @running processes but system reports I have no
 384         # children. This is likely to happen repeatedly if it happens at
 385         # all; I will log this no more than once per child process I
 386         # start.
 387         if 0 < @running.select { |uuid,j| j[:warned_waitpid_error].nil? }.size
 388           children = @running.values.collect { |j| j[:wait_thr].pid }.join ' '
 389           $stderr.puts "dispatch: IPC bug: waitpid() error (#{$!}), but I have children #{children}"
 390         end
 391         @running.each do |uuid,j| j[:warned_waitpid_error] = true end
 392       end
 393     else
 394       @running.each do |uuid, j|
 395         if j[:wait_thr].status == false
 396           pid_done = j[:wait_thr].pid
 397           j_done = j
 398         end
 399       end
 400     end
 401
 402     return if !pid_done
 403
 404     job_done = j_done[:job]
 405     $stderr.puts "dispatch: child #{pid_done} exit"
 406     $stderr.puts "dispatch: job #{job_done.uuid} end"
 407
 408     # Ensure every last drop of stdout and stderr is consumed
 409     read_pipes
 410     write_log j_done # write any remaining logs
 411
 412     if j_done[:stderr_buf] and j_done[:stderr_buf] != ''
 413       $stderr.puts j_done[:stderr_buf] + "\n"
 414     end
 415
 416     # Wait the thread (returns a Process::Status)
 417     exit_status = j_done[:wait_thr].value
 418
 419     jobrecord = Job.find_by_uuid(job_done.uuid)
 420     if exit_status.to_i != 75 and jobrecord.state == "Running"
 421       # crunch-job did not return exit code 75 (see below) and left the job in
 422       # the "Running" state, which means there was an unhandled error.  Fail
 423       # the job.
 424       jobrecord.state = "Failed"
 425       jobrecord.save!
 426     else
 427       # Don't fail the job if crunch-job didn't even get as far as
 428       # starting it. If the job failed to run due to an infrastructure
 429       # issue with crunch-job or slurm, we want the job to stay in the
 430       # queue. If crunch-job exited after losing a race to another
 431       # crunch-job process, it exits 75 and we should leave the job
 432       # record alone so the winner of the race do its thing.
 433       #
 434       # There is still an unhandled race condition: If our crunch-job
 435       # process is about to lose a race with another crunch-job
 436       # process, but crashes before getting to its "exit 75" (for
 437       # example, "cannot fork" or "cannot reach API server") then we
 438       # will assume incorrectly that it's our process's fault
 439       # jobrecord.started_at is non-nil, and mark the job as failed
 440       # even though the winner of the race is probably still doing
 441       # fine.
 442     end
 443
 444     # Invalidate the per-job auth token
 445     j_done[:job_auth].update_attributes expires_at: Time.now
 446
 447     @running.delete job_done.uuid
 448   end
 449
 450   def update_pipelines
 451     expire_tokens = @pipe_auth_tokens.dup
 452     @todo_pipelines.each do |p|
 453       pipe_auth = (@pipe_auth_tokens[p.uuid] ||= ApiClientAuthorization.
 454                    create(user: User.where('uuid=?', p.modified_by_user_uuid).first,
 455                           api_client_id: 0))
 456       puts `export ARVADOS_API_TOKEN=#{pipe_auth.api_token} && arv-run-pipeline-instance --run-pipeline-here --no-wait --instance #{p.uuid}`
 457       expire_tokens.delete p.uuid
 458     end
 459
 460     expire_tokens.each do |k, v|
 461       v.update_attributes expires_at: Time.now
 462       @pipe_auth_tokens.delete k
 463     end
 464   end
 465
 466   def run
 467     act_as_system_user
 468     @running ||= {}
 469     @pipe_auth_tokens ||= { }
 470     $stderr.puts "dispatch: ready"
 471     while !$signal[:term] or @running.size > 0
 472       read_pipes
 473       if $signal[:term]
 474         @running.each do |uuid, j|
 475           if !j[:started] and j[:sent_int] < 2
 476             begin
 477               Process.kill 'INT', j[:wait_thr].pid
 478             rescue Errno::ESRCH
 479               # No such pid = race condition + desired result is
 480               # already achieved
 481             end
 482             j[:sent_int] += 1
 483           end
 484         end
 485       else
 486         refresh_todo unless did_recently(:refresh_todo, 1.0)
 487         update_node_status
 488         unless @todo.empty? or did_recently(:start_jobs, 1.0) or $signal[:term]
 489           start_jobs
 490         end
 491         unless (@todo_pipelines.empty? and @pipe_auth_tokens.empty?) or did_recently(:update_pipelines, 5.0)
 492           update_pipelines
 493         end
 494       end
 495       reap_children
 496       select(@running.values.collect { |j| [j[:stdout], j[:stderr]] }.flatten,
 497              [], [], 1)
 498     end
 499   end
 500
 501   protected
 502
 503   def too_many_bytes_logged_for_job(j)
 504     return (j[:bytes_logged] + j[:stderr_buf_to_flush].size >
 505             Rails.configuration.crunch_limit_log_event_bytes_per_job)
 506   end
 507
 508   def too_many_events_logged_for_job(j)
 509     return (j[:events_logged] >= Rails.configuration.crunch_limit_log_events_per_job)
 510   end
 511
 512   def did_recently(thing, min_interval)
 513     @did_recently ||= {}
 514     if !@did_recently[thing] or @did_recently[thing] < Time.now - min_interval
 515       @did_recently[thing] = Time.now
 516       false
 517     else
 518       true
 519     end
 520   end
 521
 522   # send message to log table. we want these records to be transient
 523   def write_log running_job
 524     return if running_job[:log_truncated]
 525     return if running_job[:stderr_buf_to_flush] == ''
 526     begin
 527       # Truncate logs if they exceed crunch_limit_log_event_bytes_per_job
 528       # or crunch_limit_log_events_per_job.
 529       if (too_many_bytes_logged_for_job(running_job))
 530         running_job[:log_truncated] = true
 531         running_job[:stderr_buf_to_flush] =
 532           "Server configured limit reached (crunch_limit_log_event_bytes_per_job: #{Rails.configuration.crunch_limit_log_event_bytes_per_job}). Subsequent logs truncated"
 533       elsif (too_many_events_logged_for_job(running_job))
 534         running_job[:log_truncated] = true
 535         running_job[:stderr_buf_to_flush] =
 536           "Server configured limit reached (crunch_limit_log_events_per_job: #{Rails.configuration.crunch_limit_log_events_per_job}). Subsequent logs truncated"
 537       end
 538       log = Log.new(object_uuid: running_job[:job].uuid,
 539                     event_type: 'stderr',
 540                     owner_uuid: running_job[:job].owner_uuid,
 541                     properties: {"text" => running_job[:stderr_buf_to_flush]})
 542       log.save!
 543       running_job[:bytes_logged] += running_job[:stderr_buf_to_flush].size
 544       running_job[:events_logged] += 1
 545     rescue
 546       running_job[:stderr_buf] = "Failed to write logs\n" + running_job[:stderr_buf]
 547     end
 548     running_job[:stderr_buf_to_flush] = ''
 549     running_job[:stderr_flushed_at] = Time.now.to_i
 550   end
 551
 552 end
 553
 554 # This is how crunch-job child procs know where the "refresh" trigger file is
 555 ENV["CRUNCH_REFRESH_TRIGGER"] = Rails.configuration.crunch_refresh_trigger
 556
 557 Dispatcher.new.run