Improved scheduler logging and fixed wait time calculation

1 files changed, 14 insertions, 2 deletions

diff --git a/src/apscheduler/schedulers/sync.py b/src/apscheduler/schedulers/sync.py
index c49359c..748c8aa 100644
--- a/src/apscheduler/schedulers/sync.py
+++ b/src/apscheduler/schedulers/sync.py
@@ -74,7 +74,7 @@ class Scheduler:
         # Wake up the scheduler if the data store emits a significant schedule event
         self._exit_stack.enter_context(
             self.data_store.events.subscribe(
-                lambda event: self._wakeup_event.set(), {ScheduleAdded, ScheduleUpdated}
+                self._schedule_added_or_modified, {ScheduleAdded, ScheduleUpdated}
             )
         )
 
@@ -107,6 +107,10 @@ class Scheduler:
         self._state = RunState.stopped
         del self._wakeup_event
 
+    def _schedule_added_or_modified(self, event: Event) -> None:
+        self.logger.debug('Detected a %s event – waking up the scheduler', type(event).__name__)
+        self._wakeup_event.set()
+
     def add_schedule(
         self, func_or_task_id: str | Callable, trigger: Trigger, *, id: Optional[str] = None,
         args: Optional[Iterable] = None, kwargs: Optional[Mapping[str, Any]] = None,
@@ -242,6 +246,8 @@ class Scheduler:
         try:
             while self._state is RunState.started:
                 schedules = self.data_store.acquire_schedules(self.identity, 100)
+                self.logger.debug('Processing %d schedules retrieved from the data store',
+                                  len(schedules))
                 now = datetime.now(timezone.utc)
                 for schedule in schedules:
                     # Calculate a next fire time for the schedule, if possible
@@ -305,7 +311,13 @@ class Scheduler:
                 if len(schedules) < 100:
                     next_fire_time = self.data_store.get_next_schedule_run_time()
                     if next_fire_time:
-                        wait_time = (datetime.now(timezone.utc) - next_fire_time).total_seconds()
+                        wait_time = (next_fire_time - datetime.now(timezone.utc)).total_seconds()
+                        self.logger.debug('Sleeping %.3f seconds until the next fire time (%s)',
+                                          wait_time, next_fire_time)
+                    else:
+                        self.logger.debug('Waiting for any due schedules to appear')
+                else:
+                    self.logger.debug('Processing more schedules on the next iteration')
 
                 if self._wakeup_event.wait(wait_time):
                     self._wakeup_event = threading.Event()