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
 
# 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
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 



551
552
553
554
555
556
557
558
559
560
561
 
# File 'app/models/process/naf/runner.rb', line 551

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:



332
333
334
335
336
337
338
339
340
341
342
343
344
 
# File 'app/models/process/naf/runner.rb', line 332

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 escape_html("#{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 



109
110
111
112
113
114
115
116
117
118
 
# File 'app/models/process/naf/runner.rb', line 109

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 



239
240
241
242
243
244
245
246
 
# File 'app/models/process/naf/runner.rb', line 239

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 



248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
 
# File 'app/models/process/naf/runner.rb', line 248

def check_schedules
  logger.debug escape_html("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 escape_html("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 escape_html("#{machine} couldn't queue schedule because of prerequisite loop: #{jpl.message}")
          logger.warn jpl
          application_schedule.enabled = false
          application_schedule.save!
          logger.alarm escape_html("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 escape_html("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 



346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
 
# File 'app/models/process/naf/runner.rb', line 346

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 { escape_html("cleaning up dead child: #{child_job.inspect}") }
      finish_job(child_job,
                 { exit_status: (status && status.exitstatus), termination_signal: (status && status.termsig) })
    else
      # this can happen if the child is sigstopped
      logger.warn escape_html("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 escape_html("child pid: #{pid}, status: #{status.inspect}, not managed by this runner")
  end
end

#cleanup_dead_children ⇒ Object 



286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
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
 
# File 'app/models/process/naf/runner.rb', line 286

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 escape_html("#{machine} No child when we thought we had children #{@children.inspect}")
        logger.warn e
        pid = @children.first.try(:first)
        status = nil
        logger.warn escape_html("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 escape_html("Failure during cleaning up of dead child with pid: #{pid}, status: #{status}")
          logger.error escape_html("#{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 



120
121
122
123
124
125
126
127
128
 
# File 'app/models/process/naf/runner.rb', line 120

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



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

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

#escape_html(str) ⇒ Object 



599
600
601
 
# File 'app/models/process/naf/runner.rb', line 599

def escape_html(str)
  CGI::escapeHTML(str)
end

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



425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
 
# File 'app/models/process/naf/runner.rb', line 425

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) 


547
548
549
 
# File 'app/models/process/naf/runner.rb', line 547

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

#memory_available_to_spawn? ⇒ Boolean

Returns:

  • (Boolean) 


563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
 
# File 'app/models/process/naf/runner.rb', line 563

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 



99
100
101
102
103
104
105
106
107
 
# File 'app/models/process/naf/runner.rb', line 99

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 escape_html("removing invalid job #{job.inspect}")
      job.delete
  end
end

#retrieve_invocation_information ⇒ Object 



150
151
152
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
 
# File 'app/models/process/naf/runner.rb', line 150

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_signal_and_maybe_clean_up(job, signal) ⇒ Object 



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 525

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.



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

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 



367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
 
# File 'app/models/process/naf/runner.rb', line 367

def start_new_jobs
  logger.detail escape_html("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 escape_html("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 escape_html("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 escape_html("job started : #{running_job.inspect}")
      else
        # should never get here (well, hopefully)
        logger.error escape_html("#{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 escape_html("#{machine}: failure during job start")
      logger.warn e
    end
  end
  logger.debug_gross "done starting jobs"
end

#terminate_old_processes(record) ⇒ Object 



468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
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
 
# File 'app/models/process/naf/runner.rb', line 468

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 escape_html("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 escape_html("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 escape_html("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



411
412
413
414
415
416
417
418
419
420
421
422
423
 
# File 'app/models/process/naf/runner.rb', line 411

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 



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

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 escape_html("#{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 escape_html("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 



62
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
 
# File 'app/models/process/naf/runner.rb', line 62

def work
  check_gc_configurations

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

  unless machine.present?
    logger.fatal escape_html("This machine is not configued correctly (ipaddress: #{@server_address}).")
    logger.fatal escape_html("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 



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

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 escape_html("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 



205
206
207
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
 
# File 'app/models/process/naf/runner.rb', line 205

def work_machine_loop
  machine.reload

  # Check machine status
  if !machine.enabled
    logger.warn escape_html("this machine is disabled #{machine}")
    return false
  elsif machine.marked_down
    logger.warn escape_html("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

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

  return true
end