From 09b7bcea78b6b44b99e05c6856fffed6811a740d Mon Sep 17 00:00:00 2001
From: Jorrit Schaap <schaap@astron.nl>
Date: Thu, 31 Aug 2023 16:45:02 +0200
Subject: [PATCH] TMSS-2661: fixed
 determine_unschedulable_reason_and_mark_unschedulable_if_needed

---
 .../services/scheduling/lib/constraints.py    | 104 +++++++++++++-----
 SAS/TMSS/backend/src/tmss/tmssapp/tasks.py    |   1 +
 2 files changed, 75 insertions(+), 30 deletions(-)

diff --git a/SAS/TMSS/backend/services/scheduling/lib/constraints.py b/SAS/TMSS/backend/services/scheduling/lib/constraints.py
index 26c2813a3ea..a6b69c0a5ee 100644
--- a/SAS/TMSS/backend/services/scheduling/lib/constraints.py
+++ b/SAS/TMSS/backend/services/scheduling/lib/constraints.py
@@ -1267,7 +1267,7 @@ def evaluate_sky_min_distance_constraint(scheduling_unit: models.SchedulingUnitB
     return result
 
 @lru_cache(maxsize=10000)
-def get_earliest_possible_start_time_for_sky_min_elevation(scheduling_unit: models.SchedulingUnitBlueprint, lower_bound: datetime, upper_bound: datetime=None, gridder: Gridder=Gridder(), raise_if_interruped: Callable=noop) -> datetime:
+def get_earliest_possible_start_time_for_sky_min_elevation(scheduling_unit: models.SchedulingUnitBlueprint, lower_bound: datetime, upper_bound: datetime=None, gridder: Gridder=Gridder(), raise_if_interruped: Callable=noop, timeout: timedelta=timedelta(seconds=30)) -> datetime:
     # do expensive search from lower_bound until 24 hours later with small steps
     # (sky constrains are (almost) cyclic over 24 hours).
     # first occurrence where min_elevation constraint is met is taken as rough estimate of earliest_possible_start_time
@@ -1279,10 +1279,17 @@ def get_earliest_possible_start_time_for_sky_min_elevation(scheduling_unit: mode
         else:
             upper_bound = scheduling_unit.latest_possible_cycle_stop_time
 
+    _start_search_timestamp = datetime.utcnow()
+
     upper_bound = max(lower_bound, upper_bound)
     while possible_start_time <= upper_bound-scheduling_unit.specified_observation_duration:
         raise_if_interruped()
 
+        if timeout is not None:
+            _search_elapsed = datetime.utcnow() - _start_search_timestamp
+            if _search_elapsed > timeout:
+                raise TimeoutError("timeout while searching for earliest_possible_start_time for sky_min_elevation")
+
         result = evaluate_sky_min_elevation_constraint(scheduling_unit, possible_start_time, gridder=gridder)
         logger.debug('get_earliest_possible_start_time_for_sky_min_elevation %s', result)
 
@@ -1351,7 +1358,7 @@ def get_earliest_possible_start_time_for_sky_transit_offset(scheduling_unit: mod
     return None
 
 @lru_cache(maxsize=10000)
-def get_earliest_possible_start_time_for_sky_min_distance(scheduling_unit: models.SchedulingUnitBlueprint, lower_bound: datetime, upper_bound: datetime=None, gridder: Gridder=None, raise_if_interruped: Callable=noop) -> datetime:
+def get_earliest_possible_start_time_for_sky_min_distance(scheduling_unit: models.SchedulingUnitBlueprint, lower_bound: datetime, upper_bound: datetime=None, gridder: Gridder=None, raise_if_interruped: Callable=noop, timeout: timedelta=timedelta(seconds=30)) -> datetime:
     # do expensive search from lower_bound until 24 hours later with small steps
     # (sky constrains are (almost) cyclic over 24 hours).
     # first occurrence where min_distance constraint is met is taken as rough estimate of earliest_possible_start_time
@@ -1363,8 +1370,14 @@ def get_earliest_possible_start_time_for_sky_min_distance(scheduling_unit: model
         upper_bound = lower_bound + timedelta(hours=24)
     upper_bound = max(lower_bound, upper_bound)
 
+    _start_search_timestamp = datetime.utcnow()
+
     while possible_start_time < upper_bound:
         raise_if_interruped()
+        if timeout is not None:
+            _search_elapsed = datetime.utcnow() - _start_search_timestamp
+            if _search_elapsed > timeout:
+                raise TimeoutError("timeout while searching for earliest_possible_start_time for sky_min_distance")
 
         result = evaluate_sky_min_distance_constraint(scheduling_unit, possible_start_time, gridder=gridder)
         logger.debug('get_earliest_possible_start_time_for_sky_min_distance %s', result)
@@ -1727,6 +1740,8 @@ def get_earliest_possible_start_time(scheduling_unit: models.SchedulingUnitBluep
             earliest_possible_start_times.add(earliest_possible_start_time)
         except SchedulerInterruptedException:
             raise
+        except TimeoutError:
+            raise
         except Exception as e:
             logger.exception(e)
 
@@ -1868,8 +1883,9 @@ def get_weighted_start_time(scheduling_unit: models.SchedulingUnitBlueprint, low
                 logger.debug("get_weighted_start_time: SUB id=%s  weighted='%s'  -  weight=%.3f earliest='%s' optimal='%s' latest='%s'  -  window=['%s', '%s']", scheduling_unit.id, weighted_start_time, density_vs_optimal.weight, earliest_possible_start_time, optimal_start_time, latest_possible_start_time, lower_bound, upper_bound)
                 return weighted_start_time
 
-        logger.info("get_weighted_start_time: SUB id=%s returning earliest='%s'  -  window=['%s', '%s']", scheduling_unit.id, earliest_possible_start_time, lower_bound, upper_bound)
-        return earliest_possible_start_time
+        if can_run_at(scheduling_unit, earliest_possible_start_time, gridder):
+            logger.debug("get_weighted_start_time: SUB id=%s returning earliest='%s'  -  window=['%s', '%s']", scheduling_unit.id, earliest_possible_start_time, lower_bound, upper_bound)
+            return earliest_possible_start_time
 
     logger.warning("get_weighted_start_time: SUB id=%s could not compute weighted_start_time  -  window=['%s', '%s']", scheduling_unit.id, lower_bound, upper_bound)
     return None
@@ -2081,7 +2097,7 @@ def get_blocking_units(scheduling_unit: models.SchedulingUnitBlueprint, proposed
 
 def determine_unschedulable_reason_and_mark_unschedulable_if_needed(scheduling_unit: models.SchedulingUnitBlueprint, lower_bound: datetime, upper_bound: datetime, proposed_start_time: datetime=None, gridder: Gridder=None, raise_if_interruped: Callable=noop) -> models.SchedulingUnitBlueprint:
     try:
-        logger.debug("determine_unschedulable_reason_and_mark_unschedulable_if_needed: scheduling_unit id=%s", scheduling_unit.id)
+        logger.debug("determine_unschedulable_reason_and_mark_unschedulable_if_needed: id=%s project=%s lower='%s' upper='%s' proposed_start_time='%s'", scheduling_unit.id, scheduling_unit.project.name, lower_bound, upper_bound, proposed_start_time)
         if proposed_start_time is not None:
             # only check reservations as unschedulable reason for a concrete proposed_start_time, not for a window.
             if not can_run_within_station_reservations(scheduling_unit,
@@ -2115,12 +2131,17 @@ def determine_unschedulable_reason_and_mark_unschedulable_if_needed(scheduling_u
                 return mark_independent_subtasks_in_scheduling_unit_blueprint_as_unschedulable(scheduling_unit, msg)
 
         if gridder is None:
-            gridder = Gridder()
+            gridder = Gridder(Gridder.FINE_TIME_GRID)
 
+        run_window_lower = proposed_start_time if proposed_start_time else at if at else lower_bound
+        run_window_upper = proposed_start_time+scheduling_unit.specified_observation_duration if proposed_start_time else at+scheduling_unit.specified_observation_duration if at else upper_bound
         if not can_run_within_timewindow_with_constraints(scheduling_unit,
-                                                          proposed_start_time if proposed_start_time else at if at else lower_bound,
-                                                          proposed_start_time+scheduling_unit.specified_observation_duration if proposed_start_time else at+scheduling_unit.specified_observation_duration if at else upper_bound,
+                                                          run_window_lower,
+                                                          run_window_upper,
                                                           gridder, raise_if_interruped):
+            logger.debug("determine_unschedulable_reason_and_mark_unschedulable_if_needed: id=%s cannot run with constraints in window [%s, %s]. Checking each constraint...",
+                         scheduling_unit.id, run_window_lower, run_window_upper)
+
             # nope, can't run, so check each type of constraint
             unmet_constraints = []
             reasons = []
@@ -2132,13 +2153,27 @@ def determine_unschedulable_reason_and_mark_unschedulable_if_needed(scheduling_u
                         between_from = parser.parse(between["from"], ignoretz=True)
                         between_to = parser.parse(between["to"], ignoretz=True)
                         if between_from != lower_bound or between_to != upper_bound:
+                            # recurse with this between-constraint as window
                             scheduling_unit = determine_unschedulable_reason_and_mark_unschedulable_if_needed(scheduling_unit, between_from, between_to, proposed_start_time=proposed_start_time, gridder=gridder, raise_if_interruped=raise_if_interruped)
                             if scheduling_unit.status.value == models.SchedulingUnitStatus.Choices.UNSCHEDULABLE.value:
                                 return scheduling_unit
 
+                    # the above for loop did not yield an unschedulable status.
+                    # check if the proposed_start_time is within any between-window
+                    if proposed_start_time is not None:
+                        proposed_start_time_in_a_between_window = False
+                        for between in scheduling_unit.scheduling_constraints_doc['time']['between']:
+                            between_from = parser.parse(between["from"], ignoretz=True)
+                            between_to = parser.parse(between["to"], ignoretz=True)
+                            if proposed_start_time >= between_from and proposed_start_time <= between_to:
+                                proposed_start_time_in_a_between_window = True
+                                break
+                        if not proposed_start_time_in_a_between_window:
+                            return mark_independent_subtasks_in_scheduling_unit_blueprint_as_unschedulable(scheduling_unit, "the proposed start_time='%s' is not within any between constraint window: %s" % (proposed_start_time, ', '.join('[%s, %s]' % (b['from'], b['to']) for b in scheduling_unit.scheduling_constraints_doc['time']['between'])))
+
                 if 'after' in scheduling_unit.scheduling_constraints_doc['time']:
                     after = parser.parse(scheduling_unit.scheduling_constraints_doc['time']['after'], ignoretz=True)
-                    if after > lower_bound:
+                    if after > run_window_lower:
                         # recurse with the after as new lower_bound
                         scheduling_unit = determine_unschedulable_reason_and_mark_unschedulable_if_needed(scheduling_unit, after, max(after, upper_bound), proposed_start_time=proposed_start_time, gridder=gridder, raise_if_interruped=raise_if_interruped)
                         if scheduling_unit.status.value == models.SchedulingUnitStatus.Choices.UNSCHEDULABLE.value:
@@ -2168,45 +2203,54 @@ def determine_unschedulable_reason_and_mark_unschedulable_if_needed(scheduling_u
                                                                                                                        round_to_second_precision(upper_bound))
                         return mark_independent_subtasks_in_scheduling_unit_blueprint_as_unschedulable(scheduling_unit, msg)
 
-                    # use the 'at' timestamp as bounds for the remaining checks below
-                    lower_bound = proposed_start
-                    upper_bound = proposed_stop
-
             if 'sky' in scheduling_unit.scheduling_constraints_doc:
                 if 'min_elevation' in scheduling_unit.scheduling_constraints_doc['sky']:
-                    if get_earliest_possible_start_time_for_sky_min_elevation(scheduling_unit, lower_bound, upper_bound, gridder, raise_if_interruped) is None:
+                    try:
+                        if get_earliest_possible_start_time_for_sky_min_elevation(scheduling_unit, run_window_lower, run_window_upper, gridder, raise_if_interruped, timeout=timedelta(30)) is None:
+                            result = evaluate_sky_min_elevation_constraint(scheduling_unit, run_window_lower, gridder=gridder)
+                            if not result.is_constraint_met and (result.earliest_possible_start_time is None or result.earliest_possible_start_time > run_window_lower):
+                                unmet_constraints.append("sky min_elevation")
+                                reasons.append(result.message)
+                    except TimeoutError as e:
                         unmet_constraints.append("sky min_elevation")
-                        result = evaluate_sky_min_elevation_constraint(scheduling_unit, lower_bound, gridder=gridder)
-                        reasons.append(result.message)
+                        reasons.append(str(e))
 
                 if 'transit_offset' in scheduling_unit.scheduling_constraints_doc['sky']:
-                    if get_earliest_possible_start_time_for_sky_transit_offset(scheduling_unit, lower_bound, upper_bound, gridder, raise_if_interruped) is None:
-                        unmet_constraints.append("sky transit_offset")
-                        result = evaluate_sky_transit_constraint(scheduling_unit, lower_bound, gridder=gridder)
-                        reasons.append(result.message)
+                    earliest_possible_start_time = get_earliest_possible_start_time_for_sky_transit_offset(scheduling_unit, run_window_lower, run_window_upper, gridder, raise_if_interruped)
+                    if earliest_possible_start_time is None or earliest_possible_start_time <= run_window_lower  or earliest_possible_start_time >= run_window_upper:
+                        result = evaluate_sky_transit_constraint(scheduling_unit, earliest_possible_start_time or run_window_lower, gridder=gridder)
+                        if not result.is_constraint_met and (result.earliest_possible_start_time is None or result.earliest_possible_start_time > run_window_lower):
+                            unmet_constraints.append("sky transit_offset")
+                            reasons.append(result.message)
 
                 if 'min_distance' in scheduling_unit.scheduling_constraints_doc['sky']:
-                    if get_earliest_possible_start_time_for_sky_min_distance(scheduling_unit, lower_bound, upper_bound, gridder, raise_if_interruped) is None:
+                    try:
+                        if get_earliest_possible_start_time_for_sky_min_distance(scheduling_unit, run_window_lower, run_window_upper, gridder, raise_if_interruped, timeout=timedelta(30)) is None:
+                            result = evaluate_sky_min_distance_constraint(scheduling_unit, run_window_lower, gridder=gridder)
+                            if not result.is_constraint_met and (result.earliest_possible_start_time is None or result.earliest_possible_start_time > run_window_lower):
+                                unmet_constraints.append("sky min_distance")
+                                reasons.append(result.message)
+                    except TimeoutError as e:
                         unmet_constraints.append("sky min_distance")
-                        result = evaluate_sky_min_distance_constraint(scheduling_unit, lower_bound, gridder=gridder)
-                        reasons.append(result.message)
+                        reasons.append(str(e))
 
             if 'time' in scheduling_unit.scheduling_constraints_doc:
-                if get_earliest_possible_start_time_for_time_constraints(scheduling_unit, lower_bound, upper_bound, gridder, raise_if_interruped) is None:
+                if get_earliest_possible_start_time_for_time_constraints(scheduling_unit, run_window_lower, run_window_upper, gridder, raise_if_interruped) is None:
                     unmet_constraints.append("time")
 
             if 'daily' in scheduling_unit.scheduling_constraints_doc:
-                if get_earliest_possible_start_time_for_daily_constraints(scheduling_unit, lower_bound, upper_bound, gridder, raise_if_interruped) is None:
-                    unmet_constraints.append("daily")
-                    result = evaluate_daily_constraints(scheduling_unit, lower_bound, gridder=gridder)
-                    reasons.append(result.message)
+                if get_earliest_possible_start_time_for_daily_constraints(scheduling_unit, run_window_lower, run_window_upper, gridder, raise_if_interruped) is None:
+                    result = evaluate_daily_constraints(scheduling_unit, run_window_lower, gridder=gridder)
+                    if not result.is_constraint_met and (result.earliest_possible_start_time is None or result.earliest_possible_start_time > run_window_lower):
+                        unmet_constraints.append("daily")
+                        reasons.append(result.message)
 
             if unmet_constraints:
                 at = get_at_constraint_timestamp(scheduling_unit)
-                msg = ', '.join(unmet_constraints) + (" constraint is" if len(unmet_constraints)==1 else " constraints are") + " not met " + ("at %s" % (round_to_second_precision(at),) if at else "anywhere between %s and %s" % (round_to_second_precision(lower_bound), round_to_second_precision(upper_bound)))
+                msg = ', '.join(unmet_constraints) + (" constraint is" if len(unmet_constraints)==1 else " constraints are") + " not met " + ("at '%s'" % (round_to_second_precision(at),) if at else "anywhere between '%s' and '%s'" % (round_to_second_precision(lower_bound), round_to_second_precision(upper_bound)))
                 reasons = [r for r in reasons if isinstance(r, str) and len(r)]
                 if reasons:
-                    msg += '\nreason(s): ' + '\n'.join(reasons)
+                    msg += '\nreason(s):\n * ' + '\n * '.join(reasons)
                 mark_independent_subtasks_in_scheduling_unit_blueprint_as_unschedulable(scheduling_unit, msg)
             else:
                 if proposed_start_time is not None:
diff --git a/SAS/TMSS/backend/src/tmss/tmssapp/tasks.py b/SAS/TMSS/backend/src/tmss/tmssapp/tasks.py
index 8cef3970226..90c2771889f 100644
--- a/SAS/TMSS/backend/src/tmss/tmssapp/tasks.py
+++ b/SAS/TMSS/backend/src/tmss/tmssapp/tasks.py
@@ -709,6 +709,7 @@ def set_scheduling_unit_blueprint_start_times(scheduling_unit_blueprint: Schedul
 
 def mark_independent_subtasks_in_scheduling_unit_blueprint_as_unschedulable(scheduling_unit_blueprint: SchedulingUnitBlueprint, reason: str) -> models.SchedulingUnitBlueprint:
     '''Convenience method: Mark the subtasks in the scheduling_unit_blueprint that are not dependend on predecessors as unschedulable'''
+    logger.info("marking unit with id=%s as unschedulable with reason: %s", scheduling_unit_blueprint.id, reason)
     with transaction.atomic():
         for task_blueprint in scheduling_unit_blueprint.task_blueprints.all():
             mark_independent_subtasks_in_task_blueprint_as_unschedulable(task_blueprint, reason)
-- 
GitLab