D22446: Adding error handling strategy control to Scheduler

Thu Sep 19 08:18:35 BST 2019

TallFurryMan added a comment.

  Illustration for the first regression.

  F7383580: image.png <https://phabricator.kde.org/F7383580>

  I'll provide one for the second tonight when scheduler wakes up around 9:30pm. I tried to extract a log. Unrelated, but I observe that guiding is not stopped when observatory shuts down.

    (... job 11 goes under the altitude restriction ...)

    [2019-09-18T06:11:21.233 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - Checking job stage for "NGC6974-Part12" startup 2 "18/09/19 05:04" state 3
    [2019-09-18T06:11:21.234 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC6974-Part12' current altitude (15,00 degrees) crossed minimum constraint altitude (15,00 degrees), marking aborted."
    [2019-09-18T06:11:21.261 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - Job ' "NGC6974-Part12" ' is stopping current action... 3
    [2019-09-18T06:11:21.284 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - Find next job...
    [2019-09-18T06:11:21.284 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC6974-Part12' is complete."
    [2019-09-18T06:11:21.312 CEST DEBG ][     org.kde.kstars.ekos.focus] - Stopppig Focus
    [2019-09-18T06:11:21.312 CEST DEBG ][     org.kde.kstars.ekos.focus] - State: "Aborted"

    (... Oh whoops focus is restarting ? Yes, and it will finish with mount parked ...)

    [2019-09-18T06:11:22.175 CEST INFO ][     org.kde.kstars.ekos.focus] - "Restarting autofocus process..."
    [2019-09-18T06:11:22.184 CEST DEBG ][     org.kde.kstars.ekos.focus] - Starting focus with box size:  64  Subframe:  no  Autostar:  no  Full frame:  yes  [ 0 %, 85 %]  Step Size:  500  Threshold:  150  Tolerance:  10  Frames:  1  Maximum Travel:  6000
    [2019-09-18T06:11:22.185 CEST INFO ][     org.kde.kstars.ekos.focus] - "Please wait until image capture is complete..."
    [2019-09-18T06:11:22.189 CEST DEBG ][     org.kde.kstars.ekos.focus] - State: "In Progress"
    [2019-09-18T06:11:22.191 CEST INFO ][     org.kde.kstars.ekos.focus] - "Capturing image..."
    [2019-09-18T06:11:22.208 CEST INFO ][           org.kde.kstars.indi] - MoonLite :  "[INFO] Focuser reached requested position. "
    [2019-09-18T06:11:22.296 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - Checking Park Wait State...

    (... Now scheduler re-evaluates the other subsequent jobs ...)

    [2019-09-18T06:11:22.669 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - "Schedule attempt #1 for 2325-second job 'NGC6974-Part13' on row #13 starting at 18/09/19 05:45, completing at 18/09/19 06:23."
    [2019-09-18T06:11:22.670 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC6974-Part13' dark sky score is +0 at 18/09/19 06:11"
    [2019-09-18T06:11:22.671 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC6974-Part13' altitude score is -1000 at 18/09/19 06:11"
    [2019-09-18T06:11:22.671 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC6974-Part13' has a total score of -1000 at 18/09/19 06:11."
    [2019-09-18T06:11:22.715 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC6974-Part13' on row #13 passed all checks after 1 attempts, will proceed at 18/09/19 05:45 for approximately 2325 seconds, marking scheduled"
    [2019-09-18T06:11:22.715 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - "Schedule attempt #1 for 2325-second job 'NGC6974-Part14' on row #14 starting at 18/09/19 21:36, completing at 18/09/19 22:14."

    (... Goes on until last job, twice but that's expected, then Scheduler decides to sleep until job 14 ...)

    [2019-09-18T06:11:27.005 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC6974-Part14' dark sky score is +0 at 18/09/19 06:11"
    [2019-09-18T06:11:27.006 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC6974-Part14' altitude score is -1000 at 18/09/19 06:11"
    [2019-09-18T06:11:27.006 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC6974-Part14' has a total score of -1000 at 18/09/19 06:11."
    [2019-09-18T06:11:27.006 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC6974-Part14' is selected for next observation with priority #10 and score -1000."
    [2019-09-18T06:11:27.181 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC6974-Part14' scheduled for execution at 18/09/19 21:36. Observatory scheduled for shutdown until next job is ready."
    [2019-09-18T06:11:27.207 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - Checking shutdown state...
    [2019-09-18T06:11:27.207 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Starting shutdown process...
    [2019-09-18T06:11:28.170 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - Checking shutdown state...
    [2019-09-18T06:11:28.171 CEST DEBG ][           org.kde.kstars.indi] - ISD:Telescope: Parking...

    (... Scheduler falls asleep, with PHD2 still trying to guide until I close the observatory ...)

    [2019-09-18T21:36:02.671 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Scheduler is awake."
    [2019-09-18T21:36:02.674 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Scheduler is starting...
    [2019-09-18T21:36:03.701 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - "Searching in path '/home/tallfurryman/Documents/NGC6960/NGC6974-Part1/NGC6974-Part1/Light/H_Alpha', files 'NGC6974-Part1_Light_H_Alpha_480_secs*' for prefix 'NGC6974-Part1_Light_H_Alpha_480_secs'..."
    [2019-09-18T21:36:03.724 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - "> Found 'NGC6974-Part1_Light_H_Alpha_480_secs_2019-09-17T21-58-56_001'"
    [2019-09-18T21:36:03.724 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - "> Found 'NGC6974-Part1_Light_H_Alpha_480_secs_2019-09-17T22-24-31_003'"

    (... goes one enumerating ...)

    [2019-09-18T21:36:03.833 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - Frame map summary:
    [2019-09-18T21:36:03.833 CEST DEBG ][ org.kde.kstars.ekos.scheduler] -   "/home/tallfurryman/Documents/NGC6960/NGC6974-Part1/NGC6974-Part1/Light/H_Alpha/NGC6974-Part1_Light_H_Alpha_480_secs" : 4
    [2019-09-18T21:36:03.833 CEST DEBG ][ org.kde.kstars.ekos.scheduler] -   "/home/tallfurryman/Documents/NGC6960/NGC6974-Part10/NGC6974-Part10/Light/H_Alpha/NGC6974-Part10_Light_H_Alpha_480_secs" : 4
    [2019-09-18T21:36:03.834 CEST DEBG ][ org.kde.kstars.ekos.scheduler] -   "/home/tallfurryman/Documents/NGC6960/NGC6974-Part11/NGC6974-Part11/Light/H_Alpha/NGC6974-Part11_Light_H_Alpha_480_secs" : 2
    [2019-09-18T21:36:03.834 CEST DEBG ][ org.kde.kstars.ekos.scheduler] -   "/home/tallfurryman/Documents/NGC6960/NGC6974-Part12/NGC6974-Part12/Light/H_Alpha/NGC6974-Part12_Light_H_Alpha_480_secs" : 0
    [2019-09-18T21:36:03.834 CEST DEBG ][ org.kde.kstars.ekos.scheduler] -   "/home/tallfurryman/Documents/NGC6960/NGC6974-Part13/NGC6974-Part13/Light/H_Alpha/NGC6974-Part13_Light_H_Alpha_480_secs" : 0

    (... frames from job 1 to 10 are 4, 11 is 2 ...)

    [2019-09-18T21:36:05.737 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC6974-Part24' estimated to take 00h 38m 45s to complete."
    [2019-09-18T21:36:05.812 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC6974-Part25' estimated to take 00h 38m 45s to complete."
    [2019-09-18T21:36:05.831 CEST INFO ][ org.kde.kstars.ekos.scheduler] - Option to sort jobs based on priority and altitude is false
    [2019-09-18T21:36:05.870 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - "Schedule attempt #1 for 2325-second job 'NGC6974-Part1' on row #1 starting at 18/09/19 21:36, completing at 18/09/19 22:14."
    [2019-09-18T21:36:05.871 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC6974-Part1' dark sky score is +0 at 18/09/19 21:36"
    [2019-09-18T21:36:05.872 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC6974-Part1' altitude score is +73 at 18/09/19 21:36"
    [2019-09-18T21:36:05.873 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC6974-Part1' Moon separation score is +20 at 18/09/19 21:36"
    [2019-09-18T21:36:05.874 CEST INFO ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC6974-Part1' has a total score of +93 at 18/09/19 21:36."
    [2019-09-18T21:36:05.912 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC6974-Part1' on row #1 passed all checks after 1 attempts, will proceed at 18/09/19 21:36 for approximately 2325 seconds, marking scheduled"
    [2019-09-18T21:36:05.932 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - "Schedule attempt #1 for 2325-second job 'NGC6974-Part2' on row #2 starting at 18/09/19 21:36, completing at 18/09/19 22:14."
    [2019-09-18T21:36:05.951 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - "Job 'NGC6974-Part2' is scheduled to start at 18/09/19 22:16, 120 seconds after 18/09/19 22:14, in compliance with previous job completion requirement."
    [2019-09-18T21:36:05.952 CEST DEBG ][ org.kde.kstars.ekos.scheduler] - "Schedule attempt #2 for 2325-second job 'NGC6974-Part2' on row #2 starting at 18/09/19 22:16, completing at 18/09/19 22:55."

    (... goes on reevaluating all jobs to proceed instead of keeping completed jobs "completed" ...)

  I'm not sure where the regression is actually. Could be another diff in the end?

REPOSITORY
  R321 KStars

REVISION DETAIL
  https://phabricator.kde.org/D22446

To: wreissenberger, mutlaqja, TallFurryMan
Cc: kde-edu, narvaez, apol
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.kde.org/pipermail/kde-edu/attachments/20190919/09d5b8fa/attachment-0001.html>