services/api/script/crunch-dispatch.rb

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