Class: Process::Naf::Runner

Inherits:
Af::Application
  • Object
show all
Defined in:
app/models/process/naf/runner.rb

Instance Attribute Summary collapse

Instance Method Summary collapse

Constructor Details

#initialize ⇒ Runner

Returns a new instance of Runner.



49
50
51
52
53
54
55
56
57
58
59
60
61
 
# File 'app/models/process/naf/runner.rb', line 49

def initialize
  super
  opt :log_configuration_files, default: ["af.yml",
                                          "af-#{Rails.env}.yml",
                                          "naf.yml",
                                          "naf-#{Rails.env}.yml",
                                          "nafrunner.yml",
                                          "nafrunner-#{Rails.env}.yml",
                                          "#{af_name}.yml",
                                          "#{af_name}-#{Rails.env}.yml"]
  @last_machine_log_level = nil
  @metric_send_delay = ::Naf.configuration.metric_send_delay
end

Instance Attribute Details

#current_invocation ⇒ Object

Returns the value of attribute current_invocation.



6
7
8
 
# File 'app/models/process/naf/runner.rb', line 6

def current_invocation
  @current_invocation
end

#last_cleaned_up_processes ⇒ Object

Returns the value of attribute last_cleaned_up_processes.



6
7
8
 
# File 'app/models/process/naf/runner.rb', line 6

def last_cleaned_up_processes
  @last_cleaned_up_processes
end

#machine ⇒ Object

Returns the value of attribute machine.



6
7
8
 
# File 'app/models/process/naf/runner.rb', line 6

def machine
  @machine
end

Instance Method Details

#assigned_jobs(record) ⇒ Object 



573
574
575
576
577
578
579
580
581
582
583
 
# File 'app/models/process/naf/runner.rb', line 573

def assigned_jobs(record)
  if record.kind_of? ::Naf::MachineRunnerInvocation
    return ::Naf::RunningJob.started_on_invocation(record.id).readonly(false).select do |job|
      is_job_process_alive?(job)
    end
  else
    return ::Naf::RunningJob.assigned_jobs(record).select do |job|
      is_job_process_alive?(job)
    end
  end
end

#check_dead_children_not_exited_properly ⇒ Object

XXX is there a race condition where a child process exits XXX has not set pid or status yet and timeout fires? XXX i bet there is XXX so this code is here:



348
349
350
351
352
353
354
355
356
357
358
359
360
 
# File 'app/models/process/naf/runner.rb', line 348

def check_dead_children_not_exited_properly
  dead_children = []
  @children.each do |pid, child|
    unless is_job_process_alive?(child)
      dead_children << child
    end
  end

  unless dead_children.blank?
    logger.error "#{machine}: dead children even with timeout during waitpid2(): #{dead_children.inspect}"
    logger.warn "this isn't necessarily incorrect -- look for the pids to be cleaned up next round, if not: call it a bug"
  end
end

#check_gc_configurations ⇒ Object 



112
113
114
115
116
117
118
119
120
121
 
# File 'app/models/process/naf/runner.rb', line 112

def check_gc_configurations
  logger.debug "checking garbage collection configurations"
  unless @disable_gc_modifications
    # These configuration changes will help forked processes, not the runner
    ENV['RUBY_HEAP_MIN_SLOTS'] = '500000'
    ENV['RUBY_HEAP_SLOTS_INCREMENT'] = '250000'
    ENV['RUBY_HEAP_SLOTS_GROWTH_FACTOR'] = '1'
    ENV['RUBY_GC_MALLOC_LIMIT'] = '50000000'
  end
end

#check_log_level ⇒ Object 



255
256
257
258
259
260
261
262
 
# File 'app/models/process/naf/runner.rb', line 255

def check_log_level
  if machine.log_level != @last_machine_log_level
    @last_machine_log_level = machine.log_level
    unless @last_machine_log_level.blank?
      logging_configurator.parse_and_set_logger_levels(@last_machine_log_level)
    end
  end
end

#check_schedules ⇒ Object 



264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
 
# File 'app/models/process/naf/runner.rb', line 264

def check_schedules
  logger.debug "last time schedules were checked: #{::Naf::Machine.last_time_schedules_were_checked}"
  if ::Naf::Machine.is_it_time_to_check_schedules?(@check_schedules_period.minutes)
    logger.debug "it's time to check schedules"
    if ::Naf::ApplicationSchedule.try_lock_schedules
      logger.debug_gross "checking schedules"
      machine.mark_checked_schedule
      ::Naf::ApplicationSchedule.unlock_schedules

      # check scheduled tasks
      ::Naf::ApplicationSchedule.should_be_queued.each do |application_schedule|
        logger.info "scheduled application: #{application_schedule}"
        begin
          naf_boss = ::Logical::Naf::ConstructionZone::Boss.new
          # this doesn't work very well for run_group_limits in the thousands
          Range.new(0, application_schedule.application_run_group_quantum || 1, true).each do
            naf_boss.enqueue_application_schedule(application_schedule)
          end
        rescue ::Naf::HistoricalJob::JobPrerequisiteLoop => jpl
          logger.error "#{machine} couldn't queue schedule because of prerequisite loop: #{jpl.message}"
          logger.warn jpl
          application_schedule.enabled = false
          application_schedule.save!
          logger.alarm "Application Schedule disabled due to loop: #{application_schedule}"
        end
      end

      # check the runner machines
      ::Naf::Machine.enabled.up.each do |runner_to_check|
        if runner_to_check.is_stale?(@runner_stale_period.minutes)
          logger.alarm "runner is stale for #{@runner_stale_period} minutes, #{runner_to_check}"
          runner_to_check.mark_machine_down(machine)
        end
      end
    end
  end
end

#cleanup_dead_child(pid, status) ⇒ Object 



362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
 
# File 'app/models/process/naf/runner.rb', line 362

def cleanup_dead_child(pid, status)
  child_job = @children.delete(pid)

  if child_job.present?
    # Update job tags
    child_job.remove_tags([::Naf::HistoricalJob::SYSTEM_TAGS[:work]])

    if status.nil? || status.exited? || status.signaled?
      logger.info { "cleaning up dead child: #{child_job.inspect}" }
      finish_job(child_job,
                 { exit_status: (status && status.exitstatus), termination_signal: (status && status.termsig) })
      if status && status.exitstatus > 0 && !child_job.request_to_terminate
        @metric_sender.statsd.event("Naf Job Error",
              "#{child_job.inspect} finished with non-zero exit status.",
              alert_type: "error",
              tags: (::Naf.configuration.metric_tags << "naf:joberror"))
      end
    else
      # this can happen if the child is sigstopped
      logger.warn "child waited for did not exit: #{child_job.inspect}, status: #{status.inspect}"
    end
  else
    # XXX ERROR no child for returned pid -- this can't happen
    logger.warn "child pid: #{pid}, status: #{status.inspect}, not managed by this runner"
  end
end

#cleanup_dead_children ⇒ Object 



302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
 
# File 'app/models/process/naf/runner.rb', line 302

def cleanup_dead_children
  # clean up children that have exited
  logger.detail "cleaning up dead children: #{@children.length}"

  if @children.length > 0
    while @children.length > 0
      pid = nil
      status = nil
      begin
        Timeout::timeout(@loop_sleep_time) do
          pid, status = Process.waitpid2(-1)
        end
      rescue Timeout::Error
        check_dead_children_not_exited_properly
        break
      rescue Errno::ECHILD => e
        logger.error "#{machine} No child when we thought we had children #{@children.inspect}"
        logger.warn e
        pid = @children.first.try(:first)
        status = nil
        logger.warn "pulling first child off list to clean it up: pid=#{pid}"
      end

      if pid
        begin
          cleanup_dead_child(pid, status)
        rescue ActiveRecord::ActiveRecordError => are
          logger.error "Failure during cleaning up of dead child with pid: #{pid}, status: #{status}"
          logger.error "#{are.message}"
        rescue StandardError => e
          # XXX just incase a job control failure -- more code here
          logger.error "some failure during child clean up"
          logger.warn e
        end
      end
    end
  else
    logger.detail "sleeping in loop: #{@loop_sleep_time} seconds"
    sleep(@loop_sleep_time)
  end
end

#cleanup_old_processes(created_at_interval = 1.month, marked_dead_interval = 24.hours) ⇒ Object 



123
124
125
126
127
128
129
130
131
 
# File 'app/models/process/naf/runner.rb', line 123

def cleanup_old_processes(created_at_interval = 1.month, marked_dead_interval = 24.hours)
  @last_cleaned_up_processes = Time.zone.now
  logger.debug "cleaning up old processes"
  ::Naf::MachineRunner.where("created_at >= ?", Time.zone.now - created_at_interval).each do |runner|
    runner.machine_runner_invocations.recently_marked_dead(marked_dead_interval).each do |invocation|
      terminate_old_processes(invocation)
    end
  end
end

#emergency_teardown ⇒ Object

kill(0, pid) seems to fail during at_exit block so this shoots from the hip



472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
 
# File 'app/models/process/naf/runner.rb', line 472

def emergency_teardown
  return if @children.length == 0
  logger.warn "emergency teardown of #{@children.length} job(s)"
  @children.clone.each do |pid, child|
    send_signal_and_maybe_clean_up(child, "TERM")
  end

  # Wait 2 seconds
  sleep(2)

  @children.clone.each do |pid, child|
    send_signal_and_maybe_clean_up(child, "KILL")

    # force job down
    finish_job(child)
  end
end

#finish_job(running_job, updates = {}) ⇒ Object 



447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
 
# File 'app/models/process/naf/runner.rb', line 447

def finish_job(running_job, updates = {})
  # Check to see if running job still exists
  job = ::Naf::RunningJob.find_by_id(running_job.id)
  if job.present?
    job.lock_for_runner_use do
      ::Naf::HistoricalJob.transaction do
        update_historical_job(updates.merge({ finished_at: Time.zone.now }), job.id)
        job.delete
      end
    end
  else
    job = ::Naf::HistoricalJob.find_by_id(running_job.id)
    # This does not seem to be need, but just for extra measure
    if job.present?
      job.lock_for_runner_use do
        ::Naf::HistoricalJob.transaction do
          update_historical_job(updates.merge({ finished_at: Time.zone.now }), job.id)
        end
      end
    end
  end
end

#is_job_process_alive?(job) ⇒ Boolean

Returns:

  • (Boolean) 


569
570
571
 
# File 'app/models/process/naf/runner.rb', line 569

def is_job_process_alive?(job)
  return send_signal_and_maybe_clean_up(job, 0)
end

#memory_available_to_spawn? ⇒ Boolean

Returns:

  • (Boolean) 


585
586
587
588
589
590
591
592
593
594
595
596
597
598
599
600
 
# File 'app/models/process/naf/runner.rb', line 585

def memory_available_to_spawn?
  Facter.clear
  memory_size = Facter.memorysize_mb.to_f
  memory_free = Facter.memoryfree_mb.to_f
  memory_free_percentage = ((memory_free + sreclaimable_memory) / memory_size) * 100.0

  if (memory_free_percentage >= @minimum_memory_free)
    logger.detail "memory available: #{memory_free_percentage}% (free) >= " +
      "#{@minimum_memory_free}% (min percent)"
    return true
  end
  logger.alarm "#{Facter.hostname}.#{Facter.domain}: not enough memory to spawn: " +
    "#{memory_free_percentage}% (free) < #{@minimum_memory_free}% (min percent)"

  return false
end

#remove_invalid_running_jobs ⇒ Object 



102
103
104
105
106
107
108
109
110
 
# File 'app/models/process/naf/runner.rb', line 102

def remove_invalid_running_jobs
  logger.debug "looking for invalid running jobs"
  ::Naf::RunningJob.
    joins("INNER JOIN #{Naf.schema_name}.historical_jobs AS hj ON hj.id = #{Naf.schema_name}.running_jobs.id").
    where('finished_at IS NOT NULL AND hj.started_on_machine_id = ?', @machine.id).readonly(false).each do |job|
      logger.debug "removing invalid job #{job.inspect}"
      job.delete
  end
end

#retrieve_invocation_information ⇒ Object 



153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
 
# File 'app/models/process/naf/runner.rb', line 153

def retrieve_invocation_information
  begin
    repository_name = (`git remote -v`).slice(/:\S+/).sub('.git','')[1..-1]
    if repository_name.match(/fatal/)
      repository_name = nil
    end
  rescue
    repository_name = nil
  end
  branch_name = (`git rev-parse --abbrev-ref HEAD`).strip
  if branch_name.match(/fatal/)
    branch_name = nil
  end
  commit_information = (`git log --pretty="%H" -n 1`).strip
  if commit_information.match(/fatal/)
    commit_information = nil
  end
  deployment_tag = (`git describe --abbrev=0 --tag 2>&1`).strip
  if deployment_tag.match(/fatal: No names found, cannot describe anything/)
    deployment_tag = nil
  end

  {
    repository_name: repository_name,
    branch_name: branch_name,
    commit_information: commit_information,
    deployment_tag: deployment_tag
  }
end

#send_metrics ⇒ Object 



244
245
246
247
248
249
250
251
252
253
 
# File 'app/models/process/naf/runner.rb', line 244

def send_metrics
  # Only send metrics if not winding down, or winding down and only runner.
  logger.debug "checking whether it's time to send metrics"
  @current_invocation.reload
  if @current_invocation.wind_down_at.present?
    return nil if @machine.machine_runners.running.count > 0
  end
  logger.debug "sending metrics"
  @metric_sender.send_metrics
end

#send_signal_and_maybe_clean_up(job, signal) ⇒ Object 



547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
 
# File 'app/models/process/naf/runner.rb', line 547

def send_signal_and_maybe_clean_up(job, signal)
  if job.pid.nil?
    finish_job(job)

    return false
  end

  begin
    retval = Process.kill(signal, job.pid)
    logger.detail "#{retval} = kill(#{signal}, #{job.pid})"
  rescue Errno::ESRCH
    logger.detail "ESRCH = kill(#{signal}, #{job.pid})"

    # job does not exist -- mark it finished
    finish_job(job)

    return false
  end

  return true
end

#sreclaimable_memory ⇒ Object

Linux breaks out kernel cache-use memory into an SReclaimable stat in /proc/meminfo which should be counted as free, but facter does not.



604
605
606
607
608
609
610
611
612
613
614
615
616
617
618
619
 
# File 'app/models/process/naf/runner.rb', line 604

def sreclaimable_memory
  sreclaimable = 0.0
  begin
    File.readlines('/proc/meminfo').each do |l|
      if l =~ /^(?:SReclaimable):\s+(\d+)\s+\S+/
        # Convert the memory from Kilobytes to Gigabytes and
        # store it into sreclaimable
        sreclaimable = ('%.2f' % [$1.to_f / 1024.0]).to_f
        break
      end
    end
  rescue
  end

  sreclaimable
end

#start_new_jobs ⇒ Object 



389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
 
# File 'app/models/process/naf/runner.rb', line 389

def start_new_jobs
  logger.detail "starting new jobs, num children: #{@children.length}/#{machine.thread_pool_size}"
  while ::Naf::RunningJob.where(started_on_machine_id: machine.id).count < machine.thread_pool_size &&
    memory_available_to_spawn? && current_invocation.wind_down_at.blank?

    logger.debug_gross "fetching jobs because: children: #{@children.length} < #{machine.thread_pool_size} (poolsize)"
    begin
      running_job = @job_fetcher.fetch_next_job

      unless running_job.present?
        logger.debug_gross "no more jobs to run"
        break
      end

      logger.info "starting new job : #{running_job.inspect}"

      pid = running_job.historical_job.spawn
      if pid.present?
        @children[pid] = running_job
        running_job.pid = pid
        running_job.historical_job.pid = pid
        running_job.historical_job.failed_to_start = false
        running_job.historical_job.machine_runner_invocation_id = current_invocation.id
        running_job.save!
        running_job.historical_job.save!
        logger.info "job started : #{running_job.inspect}"
      else
        # should never get here (well, hopefully)
        logger.error "#{machine}: failed to execute #{running_job.inspect}"

        finish_job(running_job, { failed_to_start: true })
      end
    rescue ActiveRecord::ActiveRecordError => are
      raise
    rescue StandardError => e
      # XXX rescue for various issues
      logger.error "#{machine}: failure during job start"
      logger.warn e
    end
  end
  logger.debug_gross "done starting jobs"
end

#terminate_old_processes(record) ⇒ Object 



490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
 
# File 'app/models/process/naf/runner.rb', line 490

def terminate_old_processes(record)
  # check if any processes are hanging around and ask them
  # politely if they will please terminate
  jobs = assigned_jobs(record)
  if jobs.length == 0
    logger.detail "no jobs to remove"
    return
  end

  logger.info "number of old jobs to sift through: #{jobs.length}"
  jobs.each do |job|
    logger.detail "job still around: #{job.inspect}"
    if job.request_to_terminate == false
      logger.warn "politely asking process: #{job.pid} to terminate itself"
      job.request_to_terminate = true
      job.save!
    end
  end

  # wait
  (1..@wait_time_for_processes_to_terminate).each do |i|
    num_assigned_jobs = assigned_jobs(record).length
    return if num_assigned_jobs == 0
    logger.debug_medium "#{i}/#{@wait_time_for_processes_to_terminate}: sleeping 1 second while we wait for " +
      "#{num_assigned_jobs} assigned job(s) to terminate as requested"
    sleep(1)
  end

  # nudge them to terminate
  jobs = assigned_jobs(record)
  if jobs.length == 0
    logger.debug_gross "assigned jobs have exited after asking to terminate nicely"
    return
  end
  jobs.each do |job|
    logger.warn "sending SIG_TERM to process: #{job.inspect}"
    send_signal_and_maybe_clean_up(job, "TERM")
  end

  # wait
  (1..5).each do |i|
    num_assigned_jobs = assigned_jobs(record).length
    return if num_assigned_jobs == 0
    logger.debug_medium "#{i}/5: sleeping 1 second while we wait for #{num_assigned_jobs} assigned job(s) to terminate from SIG_TERM"
    sleep(1)
  end

  # kill with fire
  assigned_jobs(record).each do |job|
    logger.alarm "sending SIG_KILL to process: #{job.inspect}"
    send_signal_and_maybe_clean_up(job, "KILL")

    # job force job down
    finish_job(job)
  end
end

#update_historical_job(updates, historical_job_id) ⇒ Object

update_all doesn’t support “from_partition” so we have this helper



433
434
435
436
437
438
439
440
441
442
443
444
445
 
# File 'app/models/process/naf/runner.rb', line 433

def update_historical_job(updates, historical_job_id)
  updates[:updated_at] = Time.zone.now
  update_columns = updates.map{ |k,v| "#{k} = ?" }.join(", ")
  update_sql = <<-SQL
    UPDATE
      #{::Naf::HistoricalJob.partition_table_name(historical_job_id)}
    SET
      #{update_columns}
    WHERE
      id = ?
  SQL
  ::Naf::HistoricalJob.find_by_sql([update_sql] + updates.values + [historical_job_id])
end

#wind_down_runners ⇒ Object 



133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
 
# File 'app/models/process/naf/runner.rb', line 133

def wind_down_runners
  machine.machine_runners.each do |runner|
    runner.machine_runner_invocations.each do |invocation|
      if invocation.dead_at.blank?
        begin
          retval = Process.kill(0, invocation.pid)
          logger.detail "#{retval} = kill(0, #{invocation.pid}) -- process alive, marking runner invocation as winding down"
          invocation.wind_down_at = Time.zone.now
          invocation.save!
        rescue Errno::ESRCH
          logger.detail "ESRCH = kill(0, #{invocation.pid}) -- marking runner invocation as not running"
          invocation.dead_at = Time.zone.now
          invocation.save!
          terminate_old_processes(invocation)
        end
      end
    end
  end
end

#work ⇒ Object 



63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
 
# File 'app/models/process/naf/runner.rb', line 63

def work
  check_gc_configurations

  @machine = ::Naf::Machine.find_by_server_address(@server_address)

  @metric_sender = ::Logical::Naf::MetricSender.new(@metric_send_delay, @machine)

  unless machine.present?
    logger.fatal "This machine is not configued correctly (ipaddress: #{@server_address})."
    logger.fatal "Please update #{::Naf::Machine.table_name} with an entry for this machine."
    logger.fatal "Exiting..."
    exit 1
  end

  machine.lock_for_runner_use do
    cleanup_old_processes
    remove_invalid_running_jobs
    wind_down_runners

    # Create a machine runner, if it doesn't exist
    machine_runner = ::Naf::MachineRunner.
      find_or_create_by_machine_id_and_runner_cwd(machine_id: machine.id,
                                                  runner_cwd: Dir.pwd)
    # Create an invocation for this runner
    @current_invocation = ::Naf::MachineRunnerInvocation.
      create!({ machine_runner_id: machine_runner.id,
                pid: Process.pid,
                uuid: @invocation_uuid }.merge!(retrieve_invocation_information))
  end

  begin
    work_machine
  ensure
    @current_invocation.dead_at = Time.zone.now
    @current_invocation.save!
    cleanup_old_processes
  end
end

#work_machine ⇒ Object 



183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
 
# File 'app/models/process/naf/runner.rb', line 183

def work_machine
  machine.mark_alive
  machine.mark_up

  # Make sure no processes are thought to be running on this machine
  terminate_old_processes(machine) if @kill_all_runners

  logger.info "working: #{machine}"

  @children = {}

  at_exit {
    ::Af::Application.singleton.emergency_teardown
  }

  @job_fetcher = ::Logical::Naf::JobFetcher.new(machine)

  while true
    break unless work_machine_loop
    GC.start
  end

  logger.info "runner quitting"
end

#work_machine_loop ⇒ Object 



208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
 
# File 'app/models/process/naf/runner.rb', line 208

def work_machine_loop
  machine.reload

  # Check machine status
  if !machine.enabled
    logger.warn "this machine is disabled #{machine}"
    return false
  elsif machine.marked_down
    logger.warn "this machine is marked down #{machine}"
    return false
  end

  logger.debug "marking machine alive"
  machine.mark_alive

  check_log_level

  @current_invocation.reload
  if current_invocation.wind_down_at.present?
    logger.warn "invocation asked to wind down"
    if @children.length == 0
      return false;
    end
  else
    check_schedules
    start_new_jobs
  end

  send_metrics

  cleanup_dead_children
  cleanup_old_processes(1.week, 75.minutes) if (Time.zone.now - @last_cleaned_up_processes) > 1.hour

  return true
end