Merge branch 'origin-3609-arv-run' into master closes #3609
[arvados.git] / services / api / script / crunch-dispatch.rb
1 #!/usr/bin/env ruby
2
3 require 'shellwords'
4 include Process
5
6 $options = {}
7 (ARGV.any? ? ARGV : ['--jobs', '--pipelines']).each do |arg|
8   case arg
9   when '--jobs'
10     $options[:jobs] = true
11   when '--pipelines'
12     $options[:pipelines] = true
13   else
14     abort "Unrecognized command line option '#{arg}'"
15   end
16 end
17 if not ($options[:jobs] or $options[:pipelines])
18   abort "Nothing to do. Please specify at least one of: --jobs, --pipelines."
19 end
20
21 ARGV.reject! { |a| a =~ /--jobs|--pipelines/ }
22
23 $warned = {}
24 $signal = {}
25 %w{TERM INT}.each do |sig|
26   signame = sig
27   Signal.trap(sig) do
28     $stderr.puts "Received #{signame} signal"
29     $signal[:term] = true
30   end
31 end
32
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"
38   end
39 end
40
41 ENV["RAILS_ENV"] = ARGV[0] || ENV["RAILS_ENV"] || "development"
42
43 require File.dirname(__FILE__) + '/../config/boot'
44 require File.dirname(__FILE__) + '/../config/environment'
45 require 'open3'
46
47 class Dispatcher
48   include ApplicationHelper
49
50   def sysuser
51     return act_as_system_user
52   end
53
54   def refresh_todo
55     @todo = []
56     if $options[:jobs]
57       @todo = Job.queue.select(&:repository)
58     end
59     @todo_pipelines = []
60     if $options[:pipelines]
61       @todo_pipelines = PipelineInstance.queue
62     end
63   end
64
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)
72       end
73     else
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]+)\]$/)
79           tokens.shift
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
84             end
85           end
86         else
87           yield tokens
88         end
89       end
90     end
91   end
92
93   def slurm_status
94     slurm_nodes = {}
95     each_slurm_line("sinfo", "%t") do |hostname, state|
96       state.sub!(/\W+$/, "")
97       state = "down" unless %w(idle alloc down).include?(state)
98       slurm_nodes[hostname] = {state: state, job: nil}
99     end
100     each_slurm_line("squeue", "%j") do |hostname, job_uuid|
101       slurm_nodes[hostname][:job] = job_uuid if slurm_nodes[hostname]
102     end
103     slurm_nodes
104   end
105
106   def update_node_status
107     return unless Server::Application.config.crunch_job_wrapper.to_s.match /^slurm/
108     @node_state ||= {}
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.info[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.find_each do |node|
161       good_node = (node.info['slurm_state'] == 'idle')
162       need_procs.each { |node_test| good_node &&= node_test.call(node) }
163       if good_node
164         usable_nodes << node
165         if usable_nodes.count >= min_node_count
166           return usable_nodes.map { |node| node.hostname }
167         end
168       end
169     end
170     nil
171   end
172
173   def nodes_available_for_job(job)
174     # Check if there are enough idle nodes with the Job's minimum
175     # hardware requirements to run it.  If so, return an array of
176     # their names.  If not, up to once per hour, signal start_jobs to
177     # hold off launching Jobs.  This delay is meant to give the Node
178     # Manager an opportunity to make new resources available for new
179     # Jobs.
180     #
181     # The exact timing parameters here might need to be adjusted for
182     # the best balance between helping the longest-waiting Jobs run,
183     # and making efficient use of immediately available resources.
184     # These are all just first efforts until we have more data to work
185     # with.
186     nodelist = nodes_available_for_job_now(job)
187     if nodelist.nil? and not did_recently(:wait_for_available_nodes, 3600)
188       $stderr.puts "dispatch: waiting for nodes for #{job.uuid}"
189       @node_wait_deadline = Time.now + 5.minutes
190     end
191     nodelist
192   end
193
194   def fail_job job, message
195     $stderr.puts "dispatch: #{job.uuid}: #{message}"
196     begin
197       Log.new(object_uuid: job.uuid,
198               event_type: 'dispatch',
199               owner_uuid: job.owner_uuid,
200               summary: message,
201               properties: {"text" => message}).save!
202     rescue
203       $stderr.puts "dispatch: log.create failed"
204     end
205     job.state = "Failed"
206     if not job.save
207       $stderr.puts "dispatch: job.save failed"
208     end
209   end
210
211   def start_jobs
212     @todo.each do |job|
213       next if @running[job.uuid]
214
215       cmd_args = nil
216       case Server::Application.config.crunch_job_wrapper
217       when :none
218         if @running.size > 0
219             # Don't run more than one at a time.
220             return
221         end
222         cmd_args = []
223       when :slurm_immediate
224         nodelist = nodes_available_for_job(job)
225         if nodelist.nil?
226           if Time.now < @node_wait_deadline
227             break
228           else
229             next
230           end
231         end
232         cmd_args = ["salloc",
233                     "--chdir=/",
234                     "--immediate",
235                     "--exclusive",
236                     "--no-kill",
237                     "--job-name=#{job.uuid}",
238                     "--nodelist=#{nodelist.join(',')}"]
239       else
240         raise "Unknown crunch_job_wrapper: #{Server::Application.config.crunch_job_wrapper}"
241       end
242
243       if Server::Application.config.crunch_job_user
244         cmd_args.unshift("sudo", "-E", "-u",
245                          Server::Application.config.crunch_job_user,
246                          "PATH=#{ENV['PATH']}",
247                          "PERLLIB=#{ENV['PERLLIB']}",
248                          "PYTHONPATH=#{ENV['PYTHONPATH']}",
249                          "RUBYLIB=#{ENV['RUBYLIB']}",
250                          "GEM_PATH=#{ENV['GEM_PATH']}")
251       end
252
253       @authorizations ||= {}
254       if @authorizations[job.uuid] and
255           @authorizations[job.uuid].user.uuid != job.modified_by_user_uuid
256         # We already made a token for this job, but we need a new one
257         # because modified_by_user_uuid has changed (the job will run
258         # as a different user).
259         @authorizations[job.uuid].update_attributes expires_at: Time.now
260         @authorizations[job.uuid] = nil
261       end
262       if not @authorizations[job.uuid]
263         auth = ApiClientAuthorization.
264           new(user: User.where('uuid=?', job.modified_by_user_uuid).first,
265               api_client_id: 0)
266         if not auth.save
267           $stderr.puts "dispatch: auth.save failed"
268           next
269         end
270         @authorizations[job.uuid] = auth
271       end
272
273       crunch_job_bin = (ENV['CRUNCH_JOB_BIN'] || `which arv-crunch-job`.strip)
274       if crunch_job_bin == ''
275         raise "No CRUNCH_JOB_BIN env var, and crunch-job not in path."
276       end
277
278       arvados_internal = Rails.configuration.git_internal_dir
279       if not File.exists? arvados_internal
280         $stderr.puts `mkdir -p #{arvados_internal.shellescape} && cd #{arvados_internal.shellescape} && git init --bare`
281       end
282
283       git = "git --git-dir=#{arvados_internal.shellescape}"
284
285       # @fetched_commits[V]==true if we know commit V exists in the
286       # arvados_internal git repository.
287       @fetched_commits ||= {}
288       if !@fetched_commits[job.script_version]
289
290         repo_root = Rails.configuration.git_repositories_dir
291         src_repo = File.join(repo_root, job.repository + '.git')
292         if not File.exists? src_repo
293           src_repo = File.join(repo_root, job.repository, '.git')
294           if not File.exists? src_repo
295             fail_job job, "No #{job.repository}.git or #{job.repository}/.git at #{repo_root}"
296             next
297           end
298         end
299
300         # check if the commit needs to be fetched or not
301         commit_rev = `#{git} rev-list -n1 #{job.script_version.shellescape} 2>/dev/null`.chomp
302         unless $? == 0 and commit_rev == job.script_version
303           # commit does not exist in internal repository, so import the source repository using git fetch-pack
304           cmd = "#{git} fetch-pack --no-progress --all #{src_repo.shellescape}"
305           $stderr.puts cmd
306           $stderr.puts `#{cmd}`
307           unless $? == 0
308             fail_job job, "git fetch-pack failed"
309             next
310           end
311         end
312         @fetched_commits[job.script_version] = true
313       end
314
315       # @job_tags[J]==V if we know commit V has been tagged J in the
316       # arvados_internal repository. (J is a job UUID, V is a commit
317       # sha1.)
318       @job_tags ||= {}
319       if not @job_tags[job.uuid]
320         # check if the commit needs to be tagged with this job uuid
321         tag_rev = `#{git} rev-list -n1 #{job.uuid.shellescape} 2>/dev/null`.chomp
322         if $? != 0
323           # no job tag found, so create one
324           cmd = "#{git} tag #{job.uuid.shellescape} #{job.script_version.shellescape}"
325           $stderr.puts cmd
326           $stderr.puts `#{cmd}`
327           unless $? == 0
328             fail_job job, "git tag failed"
329             next
330           end
331         else
332           # job tag found, check that it has the expected revision
333           unless tag_rev == job.script_version
334             # Uh oh, the tag doesn't point to the revision we were expecting.
335             # Someone has been monkeying with the job record and/or git.
336             fail_job job, "Existing tag #{job.uuid} points to commit #{tag_rev} but expected commit #{job.script_version}"
337             next
338           end
339         end
340         @job_tags[job.uuid] = job.script_version
341       elsif @job_tags[job.uuid] != job.script_version
342         fail_job job, "Existing tag #{job.uuid} points to commit #{@job_tags[job.uuid]} but this job uses commit #{job.script_version}"
343       end
344
345       cmd_args << crunch_job_bin
346       cmd_args << '--job-api-token'
347       cmd_args << @authorizations[job.uuid].api_token
348       cmd_args << '--job'
349       cmd_args << job.uuid
350       cmd_args << '--git-dir'
351       cmd_args << arvados_internal
352
353       $stderr.puts "dispatch: #{cmd_args.join ' '}"
354
355       begin
356         i, o, e, t = Open3.popen3(*cmd_args)
357       rescue
358         $stderr.puts "dispatch: popen3: #{$!}"
359         sleep 1
360         next
361       end
362
363       $stderr.puts "dispatch: job #{job.uuid}"
364       start_banner = "dispatch: child #{t.pid} start #{Time.now.ctime.to_s}"
365       $stderr.puts start_banner
366
367       @running[job.uuid] = {
368         stdin: i,
369         stdout: o,
370         stderr: e,
371         wait_thr: t,
372         job: job,
373         buf: {stderr: '', stdout: ''},
374         started: false,
375         sent_int: 0,
376         job_auth: @authorizations[job.uuid],
377         stderr_buf_to_flush: '',
378         stderr_flushed_at: Time.new(0),
379         bytes_logged: 0,
380         events_logged: 0,
381         log_throttle_is_open: true,
382         log_throttle_reset_time: Time.now + Rails.configuration.crunch_log_throttle_period,
383         log_throttle_bytes_so_far: 0,
384         log_throttle_lines_so_far: 0,
385         log_throttle_bytes_skipped: 0,
386       }
387       i.close
388       update_node_status
389     end
390   end
391
392   # Test for hard cap on total output and for log throttling.  Returns whether
393   # the log line should go to output or not.  Modifies "line" in place to
394   # replace it with an error if a logging limit is tripped.
395   def rate_limit running_job, line
396     message = false
397     linesize = line.size
398     if running_job[:log_throttle_is_open]
399       running_job[:log_throttle_lines_so_far] += 1
400       running_job[:log_throttle_bytes_so_far] += linesize
401       running_job[:bytes_logged] += linesize
402
403       if (running_job[:bytes_logged] >
404           Rails.configuration.crunch_limit_log_bytes_per_job)
405         message = "Exceeded log limit #{Rails.configuration.crunch_limit_log_bytes_per_job} bytes (crunch_limit_log_bytes_per_job). Log will be truncated."
406         running_job[:log_throttle_reset_time] = Time.now + 100.years
407         running_job[:log_throttle_is_open] = false
408
409       elsif (running_job[:log_throttle_bytes_so_far] >
410              Rails.configuration.crunch_log_throttle_bytes)
411         remaining_time = running_job[:log_throttle_reset_time] - Time.now
412         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"
413         running_job[:log_throttle_is_open] = false
414
415       elsif (running_job[:log_throttle_lines_so_far] >
416              Rails.configuration.crunch_log_throttle_lines)
417         remaining_time = running_job[:log_throttle_reset_time] - Time.now
418         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"
419         running_job[:log_throttle_is_open] = false
420       end
421     end
422
423     if not running_job[:log_throttle_is_open]
424       # Don't log anything if any limit has been exceeded. Just count lossage.
425       running_job[:log_throttle_bytes_skipped] += linesize
426     end
427
428     if message
429       # Yes, write to logs, but use our "rate exceeded" message
430       # instead of the log message that exceeded the limit.
431       line.replace message
432       true
433     else
434       running_job[:log_throttle_is_open]
435     end
436   end
437
438   def read_pipes
439     @running.each do |job_uuid, j|
440       job = j[:job]
441
442       now = Time.now
443       if now > j[:log_throttle_reset_time]
444         # It has been more than throttle_period seconds since the last
445         # checkpoint so reset the throttle
446         if j[:log_throttle_bytes_skipped] > 0
447           message = "#{job_uuid} ! Skipped #{j[:log_throttle_bytes_skipped]} bytes of log"
448           $stderr.puts message
449           j[:stderr_buf_to_flush] << "#{Time.now.ctime.to_s} #{message}\n"
450         end
451
452         j[:log_throttle_reset_time] = now + Rails.configuration.crunch_log_throttle_period
453         j[:log_throttle_bytes_so_far] = 0
454         j[:log_throttle_lines_so_far] = 0
455         j[:log_throttle_bytes_skipped] = 0
456         j[:log_throttle_is_open] = true
457       end
458
459       j[:buf].each do |stream, streambuf|
460         # Read some data from the child stream
461         buf = ''
462         begin
463           # It's important to use a big enough buffer here. When we're
464           # being flooded with logs, we must read and discard many
465           # bytes at once. Otherwise, we can easily peg a CPU with
466           # time-checking and other loop overhead. (Quick tests show a
467           # 1MiB buffer working 2.5x as fast as a 64 KiB buffer.)
468           #
469           # So don't reduce this buffer size!
470           buf = j[stream].read_nonblock(2**20)
471         rescue Errno::EAGAIN, EOFError
472         end
473
474         # Short circuit the counting code if we're just going to throw
475         # away the data anyway.
476         if not j[:log_throttle_is_open]
477           j[:log_throttle_bytes_skipped] += streambuf.size + buf.size
478           streambuf.replace ''
479           next
480         elsif buf == ''
481           next
482         end
483
484         # Append to incomplete line from previous read, if any
485         streambuf << buf
486
487         bufend = ''
488         streambuf.each_line do |line|
489           if not line.end_with? $/
490             if line.size > Rails.configuration.crunch_log_throttle_bytes
491               # Without a limit here, we'll use 2x an arbitrary amount
492               # of memory, and waste a lot of time copying strings
493               # around, all without providing any feedback to anyone
494               # about what's going on _or_ hitting any of our throttle
495               # limits.
496               #
497               # Here we leave "line" alone, knowing it will never be
498               # sent anywhere: rate_limit() will reach
499               # crunch_log_throttle_bytes immediately. However, we'll
500               # leave [...] in bufend: if the trailing end of the long
501               # line does end up getting sent anywhere, it will have
502               # some indication that it is incomplete.
503               bufend = "[...]"
504             else
505               # If line length is sane, we'll wait for the rest of the
506               # line to appear in the next read_pipes() call.
507               bufend = line
508               break
509             end
510           end
511           # rate_limit returns true or false as to whether to actually log
512           # the line or not.  It also modifies "line" in place to replace
513           # it with an error if a logging limit is tripped.
514           if rate_limit j, line
515             $stderr.print "#{job_uuid} ! " unless line.index(job_uuid)
516             $stderr.puts line
517             pub_msg = "#{Time.now.ctime.to_s} #{line.strip}\n"
518             j[:stderr_buf_to_flush] << pub_msg
519           end
520         end
521
522         # Leave the trailing incomplete line (if any) in streambuf for
523         # next time.
524         streambuf.replace bufend
525       end
526       # Flush buffered logs to the logs table, if appropriate. We have
527       # to do this even if we didn't collect any new logs this time:
528       # otherwise, buffered data older than seconds_between_events
529       # won't get flushed until new data arrives.
530       write_log j
531     end
532   end
533
534   def reap_children
535     return if 0 == @running.size
536     pid_done = nil
537     j_done = nil
538
539     if false
540       begin
541         pid_done = waitpid(-1, Process::WNOHANG | Process::WUNTRACED)
542         if pid_done
543           j_done = @running.values.
544             select { |j| j[:wait_thr].pid == pid_done }.
545             first
546         end
547       rescue SystemCallError
548         # I have @running processes but system reports I have no
549         # children. This is likely to happen repeatedly if it happens at
550         # all; I will log this no more than once per child process I
551         # start.
552         if 0 < @running.select { |uuid,j| j[:warned_waitpid_error].nil? }.size
553           children = @running.values.collect { |j| j[:wait_thr].pid }.join ' '
554           $stderr.puts "dispatch: IPC bug: waitpid() error (#{$!}), but I have children #{children}"
555         end
556         @running.each do |uuid,j| j[:warned_waitpid_error] = true end
557       end
558     else
559       @running.each do |uuid, j|
560         if j[:wait_thr].status == false
561           pid_done = j[:wait_thr].pid
562           j_done = j
563         end
564       end
565     end
566
567     return if !pid_done
568
569     job_done = j_done[:job]
570     $stderr.puts "dispatch: child #{pid_done} exit"
571     $stderr.puts "dispatch: job #{job_done.uuid} end"
572
573     # Ensure every last drop of stdout and stderr is consumed.
574     read_pipes
575     # Reset flush timestamp to make sure log gets written.
576     j_done[:stderr_flushed_at] = Time.new(0)
577     # Write any remaining logs.
578     write_log j_done
579
580     j_done[:buf].each do |stream, streambuf|
581       if streambuf != ''
582         $stderr.puts streambuf + "\n"
583       end
584     end
585
586     # Wait the thread (returns a Process::Status)
587     exit_status = j_done[:wait_thr].value.exitstatus
588
589     jobrecord = Job.find_by_uuid(job_done.uuid)
590     if exit_status != 75 and jobrecord.state == "Running"
591       # crunch-job did not return exit code 75 (see below) and left the job in
592       # the "Running" state, which means there was an unhandled error.  Fail
593       # the job.
594       jobrecord.state = "Failed"
595       if not jobrecord.save
596         $stderr.puts "dispatch: jobrecord.save failed"
597       end
598     else
599       # Don't fail the job if crunch-job didn't even get as far as
600       # starting it. If the job failed to run due to an infrastructure
601       # issue with crunch-job or slurm, we want the job to stay in the
602       # queue. If crunch-job exited after losing a race to another
603       # crunch-job process, it exits 75 and we should leave the job
604       # record alone so the winner of the race do its thing.
605       #
606       # There is still an unhandled race condition: If our crunch-job
607       # process is about to lose a race with another crunch-job
608       # process, but crashes before getting to its "exit 75" (for
609       # example, "cannot fork" or "cannot reach API server") then we
610       # will assume incorrectly that it's our process's fault
611       # jobrecord.started_at is non-nil, and mark the job as failed
612       # even though the winner of the race is probably still doing
613       # fine.
614     end
615
616     # Invalidate the per-job auth token
617     j_done[:job_auth].update_attributes expires_at: Time.now
618
619     @running.delete job_done.uuid
620   end
621
622   def update_pipelines
623     expire_tokens = @pipe_auth_tokens.dup
624     @todo_pipelines.each do |p|
625       pipe_auth = (@pipe_auth_tokens[p.uuid] ||= ApiClientAuthorization.
626                    create(user: User.where('uuid=?', p.modified_by_user_uuid).first,
627                           api_client_id: 0))
628       puts `export ARVADOS_API_TOKEN=#{pipe_auth.api_token} && arv-run-pipeline-instance --run-pipeline-here --no-wait --instance #{p.uuid}`
629       expire_tokens.delete p.uuid
630     end
631
632     expire_tokens.each do |k, v|
633       v.update_attributes expires_at: Time.now
634       @pipe_auth_tokens.delete k
635     end
636   end
637
638   def run
639     act_as_system_user
640     @running ||= {}
641     @pipe_auth_tokens ||= { }
642     $stderr.puts "dispatch: ready"
643     while !$signal[:term] or @running.size > 0
644       read_pipes
645       if $signal[:term]
646         @running.each do |uuid, j|
647           if !j[:started] and j[:sent_int] < 2
648             begin
649               Process.kill 'INT', j[:wait_thr].pid
650             rescue Errno::ESRCH
651               # No such pid = race condition + desired result is
652               # already achieved
653             end
654             j[:sent_int] += 1
655           end
656         end
657       else
658         refresh_todo unless did_recently(:refresh_todo, 1.0)
659         update_node_status unless did_recently(:update_node_status, 1.0)
660         unless @todo.empty? or did_recently(:start_jobs, 1.0) or $signal[:term]
661           start_jobs
662         end
663         unless (@todo_pipelines.empty? and @pipe_auth_tokens.empty?) or did_recently(:update_pipelines, 5.0)
664           update_pipelines
665         end
666       end
667       reap_children
668       select(@running.values.collect { |j| [j[:stdout], j[:stderr]] }.flatten,
669              [], [], 1)
670     end
671   end
672
673   protected
674
675   def did_recently(thing, min_interval)
676     @did_recently ||= {}
677     if !@did_recently[thing] or @did_recently[thing] < Time.now - min_interval
678       @did_recently[thing] = Time.now
679       false
680     else
681       true
682     end
683   end
684
685   # send message to log table. we want these records to be transient
686   def write_log running_job
687     return if running_job[:stderr_buf_to_flush] == ''
688
689     # Send out to log event if buffer size exceeds the bytes per event or if
690     # it has been at least crunch_log_seconds_between_events seconds since
691     # the last flush.
692     if running_job[:stderr_buf_to_flush].size > Rails.configuration.crunch_log_bytes_per_event or
693         (Time.now - running_job[:stderr_flushed_at]) >= Rails.configuration.crunch_log_seconds_between_events
694       begin
695         log = Log.new(object_uuid: running_job[:job].uuid,
696                       event_type: 'stderr',
697                       owner_uuid: running_job[:job].owner_uuid,
698                       properties: {"text" => running_job[:stderr_buf_to_flush]})
699         log.save!
700         running_job[:events_logged] += 1
701       rescue => exception
702         $stderr.puts "Failed to write logs"
703         $stderr.puts exception.backtrace
704       end
705       running_job[:stderr_buf_to_flush] = ''
706       running_job[:stderr_flushed_at] = Time.now
707     end
708   end
709 end
710
711 # This is how crunch-job child procs know where the "refresh" trigger file is
712 ENV["CRUNCH_REFRESH_TRIGGER"] = Rails.configuration.crunch_refresh_trigger
713
714 Dispatcher.new.run