diff --git a/SAS/TMSS/backend/services/scheduling/lib/dynamic_scheduling.py b/SAS/TMSS/backend/services/scheduling/lib/dynamic_scheduling.py index a13f9b5d5e364de333846d6580673e8ecd2aaa49..7ecf79bd838f8b97cf4c8c28b31c116b339e663e 100644 --- a/SAS/TMSS/backend/services/scheduling/lib/dynamic_scheduling.py +++ b/SAS/TMSS/backend/services/scheduling/lib/dynamic_scheduling.py @@ -213,7 +213,7 @@ class Scheduler: logger.info("Scheduler skipping update of dynamic schedule because it is not enabled in the settings") logger.info("Scheduler full schedule computation finished.") - self.log_schedule() + self.log_schedule(log_level=logging.INFO) def schedule_fixed_time_scheduling_units(self): ''' Schedule all schedulable fixed_time scheduling units.''' @@ -259,6 +259,8 @@ class Scheduler: msg = "fixed_time-scheduled scheduling unit id=%d cannot be scheduled at '%s'" % (schedulable_unit.id, start_time) logger.warning(msg) mark_independent_subtasks_in_scheduling_unit_blueprint_as_unschedulable(schedulable_unit, reason=msg) + + self.log_schedule(log_level=logging.DEBUG) except Exception as e: logger.exception("Could not schedule fixed_time-scheduled scheduling unit id=%d: %s", schedulable_unit.id, e) else: @@ -450,6 +452,8 @@ class Scheduler: for scheduled_scheduling_unit in get_scheduled_scheduling_units().filter(scheduling_constraints_doc__scheduler='dynamic').exclude(id=scheduled_scheduling_unit.id).all(): unschedule_subtasks_in_scheduling_unit_blueprint(scheduled_scheduling_unit) + self.log_schedule(log_level=logging.DEBUG) + # return the scheduled scheduling_unit, early exit out of looping over priority queues. return scheduled_scheduling_unit @@ -524,6 +528,8 @@ class Scheduler: logger.info("mid-term schedule: next scheduling unit id=%s '%s' start_time=%s", scheduling_unit.id, scheduling_unit.name, start_time) update_subtasks_start_times_for_scheduling_unit(scheduling_unit, start_time) + self.log_schedule(log_level=logging.DEBUG) + # keep track of the lower_bound_start_time based on last sub.on_sky_stop_time and gap lower_bound_start_time = scheduling_unit.on_sky_stop_time + DEFAULT_INTER_OBSERVATION_GAP @@ -546,21 +552,24 @@ class Scheduler: logger.info("Estimating mid-term schedule... finished") - def log_schedule(self): + def log_schedule(self, log_level: int=logging.INFO): '''Log the upcoming schedule in a table like format''' try: + if not logger.isEnabledFor(log_level): + return + units_in_schedule = models.SchedulingUnitBlueprint.objects.filter( status__value__in=models.SchedulingUnitStatus.SCHEDULABLE_ACTIVE_OR_FINISHED_STATUS_VALUES).filter( scheduled_start_time__isnull=False).filter( scheduled_start_time__gte=datetime.utcnow()).order_by('scheduled_start_time').all() if units_in_schedule: - logger.info("-----------------------------------------------------------------") - logger.info("Schedule:") + logger.log(log_level, "-----------------------------------------------------------------") + logger.log(log_level, "Schedule:") for unit in units_in_schedule: try: transit_time, transit_offset, elevation = get_transit_timestamp_offset_and_elevation(unit, unit.scheduled_start_time) - logger.info( + logger.log(log_level, " id=% 3d name=%s start_time='%s'[UTC] status=%s transit_offset=% 5d[min] elevation=% 3.1f[deg]", unit.id, ("'%s'" % (unit.name[:32],)).ljust(34), @@ -570,7 +579,7 @@ class Scheduler: Angle(elevation, astropy.units.rad).degree) except Exception as e: logger.warning(e) - logger.info("-----------------------------------------------------------------") + logger.log(log_level, "-----------------------------------------------------------------") # TODO: report on schedule density except Exception as e: logger.warning(e)