Check for timed out active tasks #15231

yrudman · 2017-05-25T17:01:19Z

Issue:
If reporting worker killed (kill -9 <pid>) when report is still running than task status stays Running forever.

original BZ: https://bugzilla.redhat.com/show_bug.cgi?id=1397600

This PR:

adds active_task_timeout and task_timeout_check_frequency to settings.yml
adds check for timed out tasks to MiqScheduleWorker

@miq-bot add-label bug, core

\cc @jrafanie @gtanzillo

jrafanie · 2017-05-26T14:50:52Z

app/models/miq_schedule_worker/runner.rb

+  def schedule_check_for_task_timeout
+    every = worker_settings[:task_timeout_check_frequency]
+    scheduler = scheduler_for(:scheduler)
+    scheduler.schedule_every(every, :first_at => Time.current + 1.minute) do


@yrudman have you tested that rufus supports ActiveSupport::TimeWithZone?

irb(main):003:0> Time.current.class => ActiveSupport::TimeWithZone

i've done manual testing: leaving active records in DB and restarting server - works

>> require 'rufus-scheduler' >> s = Rufus::Scheduler.new >> n = Time.current => Fri, 26 May 2017 15:50:17 UTC +00:00 >> p [ :scheduled_at, n, n.to_f ] [:scheduled_at, Fri, 26 May 2017 15:50:17 UTC +00:00, 1495813817.563702] => [:scheduled_at, Fri, 26 May 2017 15:50:17 UTC +00:00, 1495813817.563702]

jrafanie · 2017-05-26T14:51:54Z

app/models/miq_task.rb

+  scope :timed_out, -> { where("updated_on < ?", Time.now.utc - ::Settings.task.active_task_timeout.to_i_with_method) }
+
+  def self.update_status_for_timed_out_active_tasks
+    MiqTask.active.timed_out.no_associated_job.find_each do |task|


What about tasks that have a job but are "timed out"? What cleans them up?

I think Job should have its own implementation for checking stalled job due to worker killing. There is 'timing out' implementation for job but i think it would not accommodate killing worker.

jrafanie · 2017-05-26T14:53:25Z

app/models/miq_task.rb

@@ -33,6 +33,17 @@ class MiqTask < ApplicationRecord
    t.grouping(Arel::Nodes::Case.new(t[:state]).when(STATE_FINISHED).then(t[:status]).else(t[:state]))
  end)

+  scope :active, -> { where(:state => STATE_ACTIVE) }
+  scope :no_associated_job, -> { where.not("id IN (SELECT miq_task_id from jobs)") }
+  scope :timed_out, -> { where("updated_on < ?", Time.now.utc - ::Settings.task.active_task_timeout.to_i_with_method) }


Nitpick, can you align the ->

jrafanie · 2017-05-26T14:55:52Z

app/models/miq_task.rb

+
+  def self.update_status_for_timed_out_active_tasks
+    MiqTask.active.timed_out.no_associated_job.find_each do |task|
+      task.update_status(STATE_FINISHED, STATUS_ERROR,


Was there a reason to not use STATUS_TIMEOUT?

Timeout not present as possible state and task with status Timeout will not be shown on Task management screens:

I think we should add `Timeout` to a list of possible state filter.
@gtanzillo what do you think, should we first allow timed out tasks to be visible on task management screens and change this PR to set status to STATUS_TIMEOUT ?
or proceed with with this PR setting timed out task Error status ?
or set status to Warn ?

jrafanie · 2017-05-26T14:58:26Z

config/settings.yml

@@ -1299,6 +1301,7 @@
      :session_timeout_interval: 30.seconds
      :storage_file_collection_interval: 1.days
      :storage_file_collection_time_utc: 21600
+      :task_timeout_check_frequency: 1.hour


I don't know what's are the correct numbers here...

1.hour here seems reasonable. We don't want to be checking too often but, we also don't want to have tasks sitting in an active state for an extended period of time when they are already dead.

jrafanie · 2017-05-26T14:59:16Z

spec/models/miq_schedule_worker/jobs_spec.rb

@@ -49,4 +49,15 @@
      )
    end
  end
+
+  describe "#check_for_timed_out_active_tasks" do
+    it "queue request to updtae status for timed out tasks" do


typo: update.... Maybe enqueues update_status_for_timed_out_active_tasks

Thank you for noticing it !

gtanzillo · 2017-05-26T16:05:39Z

spec/models/miq_task_spec.rb

+      end
+
+      context "task is not active" do
+        it "does not updates status to 'Error' if task state is 'Finished'" do


Typo here - "updates" should be "update"

gtanzillo · 2017-05-26T16:05:53Z

spec/models/miq_task_spec.rb

+        job.miq_task
+      end
+
+      it "does not updates status to 'Error'" do


Same typo here...

gtanzillo · 2017-05-26T16:11:16Z

config/settings.yml

@@ -1129,6 +1129,8 @@
  :max_parallel_scans_per_host: 1
  :max_qitems_per_scan_request: 0
  :watchdog_interval: 1.minute
+:task:
+  :active_task_timeout: 5.hours


6.hours somehow feels better here. I can't explain why, though :)

gtanzillo · 2017-05-26T16:11:34Z

config/settings.yml

@@ -1299,6 +1301,7 @@
      :session_timeout_interval: 30.seconds
      :storage_file_collection_interval: 1.days
      :storage_file_collection_time_utc: 21600
+      :task_timeout_check_frequency: 1.hour


1.hour here seems reasonable. We don't want to be checking too often but, we also don't want to have tasks sitting in an active state for an extended period of time when they are already dead.

yrudman · 2017-05-30T13:40:36Z

@miq-bot assign @gtanzillo

jrafanie · 2017-05-30T16:10:22Z

app/models/miq_task.rb

+
+  def self.update_status_for_timed_out_active_tasks
+    MiqTask.active.timed_out.no_associated_job.find_each do |task|
+      task.update_status(STATE_FINISHED, STATUS_ERROR,


I'm still confused by the STATUS_ERROR. We should fix this in a followup so the UI displays timed out tasks.

ok, i will look at it

BZ: https://bugzilla.redhat.com/show_bug.cgi?id=1397600

…tive_tasks

…task_timeout $ runner_spec

miq-bot · 2017-05-30T22:58:48Z

Checked commits yrudman/manageiq@032d422~...8051e5e with ruby 2.2.6, rubocop 0.47.1, and haml-lint 0.20.0
6 files checked, 0 offenses detected
Everything looks fine. 🍰

jrafanie · 2017-05-31T14:59:51Z

@gtanzillo what versions should this go back to?

yrudman · 2017-05-31T19:11:59Z

@miq-bot add-label fine/yes, euwe/yes

simaishi · 2017-06-01T18:19:18Z

@yrudman Please remove euwe/conflict label when you have an Euwe PR. Thanks!

simaishi · 2017-06-05T15:43:32Z

Backported to Euwe via #15277

…eout Check for timed out active tasks (cherry picked from commit 7fce59f) https://bugzilla.redhat.com/show_bug.cgi?id=1460349

simaishi · 2017-06-09T20:03:01Z

Fine backport details:

$ git log -1
commit 83c3180ddc1b532d3bcf10f86337fe433e721033
Author: Joe Rafaniello <[email protected]>
Date:   Wed May 31 10:59:27 2017 -0400

    Merge pull request #15231 from yrudman/introduce-report-execution-timeout
    
    Check for timed out active tasks
    (cherry picked from commit 7fce59fb0dd5ac4ecc01d5163a7bf55ffbe495b9)
    
    https://bugzilla.redhat.com/show_bug.cgi?id=1460349

miq-bot added bug core labels May 25, 2017

yrudman force-pushed the introduce-report-execution-timeout branch 4 times, most recently from e6e182e to 3970a3b Compare May 25, 2017 22:48

jrafanie reviewed May 26, 2017

View reviewed changes

gtanzillo reviewed May 26, 2017

View reviewed changes

miq-bot assigned gtanzillo May 30, 2017

jrafanie reviewed May 30, 2017

View reviewed changes

yrudman added 6 commits May 30, 2017 18:50

added settings for checking task timeout

032d422

BZ: https://bugzilla.redhat.com/show_bug.cgi?id=1397600

task.rb: added method to update task's status to Error if task timed out

6f3f8fa

BZ: https://bugzilla.redhat.com/show_bug.cgi?id=1397600

added check for timed out tasks to MiqScheduleWorker

0e49537

BZ: https://bugzilla.redhat.com/show_bug.cgi?id=1397600

rspec for MiqTask.update_status_for_timed_out_active_tasks

7f70cc5

miq_schedule_worker/jobs_spec: added test for #check_for_timed_out_ac…

942405c

…tive_tasks

miq_schedule_worker/runner_spec: added test for ##schedule_check_for_…

8051e5e

…task_timeout $ runner_spec

yrudman force-pushed the introduce-report-execution-timeout branch from ae224d7 to 8051e5e Compare May 30, 2017 22:52

jrafanie merged commit 7fce59f into ManageIQ:master May 31, 2017

jrafanie added this to the Sprint 62 Ending Jun 5, 2017 milestone May 31, 2017

jrafanie deleted the introduce-report-execution-timeout branch May 31, 2017 14:59

miq-bot added the euwe/yes label May 31, 2017

miq-bot added the fine/yes label May 31, 2017

simaishi added the euwe/conflict label Jun 1, 2017

yrudman mentioned this pull request Jun 1, 2017

[EUWE] Check for timed out active tasks #15277

Merged

simaishi removed the euwe/conflict label Jun 1, 2017

simaishi added euwe/backported and removed euwe/yes labels Jun 5, 2017

simaishi pushed a commit that referenced this pull request Jun 9, 2017

Merge pull request #15231 from yrudman/introduce-report-execution-tim…

83c3180

…eout Check for timed out active tasks (cherry picked from commit 7fce59f) https://bugzilla.redhat.com/show_bug.cgi?id=1460349

simaishi added fine/backported and removed fine/yes labels Jun 9, 2017

yrudman mentioned this pull request Jun 14, 2017

Format time interval for log message #15370

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Check for timed out active tasks #15231

Check for timed out active tasks #15231

yrudman commented May 25, 2017

jrafanie May 26, 2017

yrudman May 26, 2017

yrudman May 26, 2017

jrafanie May 26, 2017

yrudman May 26, 2017

jrafanie May 26, 2017

yrudman May 26, 2017

jrafanie May 26, 2017

yrudman May 26, 2017

jrafanie May 26, 2017

yrudman May 26, 2017

gtanzillo May 26, 2017

jrafanie May 26, 2017

yrudman May 26, 2017

gtanzillo May 26, 2017

yrudman May 26, 2017

gtanzillo May 26, 2017

yrudman May 26, 2017

gtanzillo May 26, 2017

yrudman May 26, 2017

gtanzillo May 26, 2017

yrudman commented May 30, 2017

jrafanie May 30, 2017

yrudman May 30, 2017

miq-bot commented May 30, 2017

jrafanie commented May 31, 2017

yrudman commented May 31, 2017

simaishi commented Jun 1, 2017

simaishi commented Jun 5, 2017

simaishi commented Jun 9, 2017

Check for timed out active tasks #15231

Check for timed out active tasks #15231

Conversation

yrudman commented May 25, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

yrudman commented May 30, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

miq-bot commented May 30, 2017

jrafanie commented May 31, 2017

yrudman commented May 31, 2017

simaishi commented Jun 1, 2017

simaishi commented Jun 5, 2017

simaishi commented Jun 9, 2017