detect resume from sleep without logind (#2360, phase 3)

src/vorta/scheduler.py

@@ -26,6 +26,10 @@
 
 logger = logging.getLogger(__name__)
 
+RESCHEDULE_INTERVAL_MS = 15 * 60 * 1000
+WAKE_CHECK_INTERVAL_MS = 5 * 60 * 1000
+WAKE_GAP_THRESHOLD = timedelta(minutes=10)
+
 
 class ScheduleStatusType(enum.Enum):
     SCHEDULED = enum.auto()  # date provided
@@ -55,11 +59,10 @@ def __init__(self) -> None:
         # pausing will prevent scheduling for a specified time
         self.pauses: dict[int, tuple[dt, QtCore.QTimer]] = dict()
 
-        # Set additional timer to make sure background tasks stay scheduled.
-        # E.g. after hibernation
+        # Periodic reschedule, in case a run was missed
         self.qt_timer = QTimer()
         self.qt_timer.timeout.connect(self.reload_all_timers)
-        self.qt_timer.setInterval(15 * 60 * 1000)
+        self.qt_timer.setInterval(RESCHEDULE_INTERVAL_MS)
         self.qt_timer.start()
 
         # connect signals
@@ -81,15 +84,37 @@ def __init__(self) -> None:
             self.bus = bus
             self.bus.connect(service, path, interface, name, "b", self.loginSuspendNotify)
         else:
-            logger.warning('Failed to connect to DBUS interface to detect sleep/resume events')
+            logger.info('No systemd-logind to notify us of sleep/resume, watching for clock gaps as well')
+
+        self._last_wake_check = dt.now()
+        self.wake_timer = QTimer()
+        self.wake_timer.timeout.connect(self.checkForResume)
+        self.wake_timer.setInterval(WAKE_CHECK_INTERVAL_MS)
+        self.wake_timer.start()
 
     @QtCore.pyqtSlot(bool)
     def loginSuspendNotify(self, suspend: bool) -> None:
         if not suspend:
             logger.debug("Got login suspend/resume notification")
-            # Defensively refetch in case the network status didn't arrive
-            self._net_up = self.net_status.is_network_active()
-            self.reload_all_timers()
+            self._handle_resume()
+
+    @QtCore.pyqtSlot()
+    def checkForResume(self) -> None:
+        now = dt.now()
+        elapsed = now - self._last_wake_check
+        self._last_wake_check = now
+
+        if elapsed < WAKE_GAP_THRESHOLD:
+            return
+
+        logger.debug('Clock jumped %s since the last wake check, assuming the machine slept', elapsed)
+        self._handle_resume()
+
+    def _handle_resume(self) -> None:
+        self._last_wake_check = dt.now()
+        # Defensively refetch in case the network status didn't arrive
+        self._net_up = self.net_status.is_network_active()
+        self.reload_all_timers()
 
     @QtCore.pyqtSlot(bool)
     def networkStatusChanged(self, up: bool):

tests/unit/test_scheduler.py

@@ -25,6 +25,19 @@ def clockmock(monkeypatch):
     return datetime_mock
 
 
+@pytest.fixture(autouse=True)
+def stopped_wake_timers(qapp, monkeypatch):
+    """The app keeps every scheduler alive, so a tick would land in an unrelated later test."""
+    qapp.scheduler.wake_timer.stop()
+    original_init = VortaScheduler.__init__
+
+    def init_with_stopped_wake_timer(self, *args, **kwargs):
+        original_init(self, *args, **kwargs)
+        self.wake_timer.stop()
+
+    monkeypatch.setattr(VortaScheduler, '__init__', init_with_stopped_wake_timer)
+
+
 def prepare(func):
     """Decorator adding common preparation steps."""
 
@@ -377,3 +390,45 @@ def test_set_timer_records_skip_when_network_down_for_catchup(clockmock):
     # Re-evaluating the same missed run must not add a second row.
     scheduler.set_timer_for_profile(profile.id)
     assert JobModel.select().count() == jobs_before + 1
+
+
+def test_wall_clock_gap_is_treated_as_a_resume(mocker, clockmock):
+    """Without logind, a jump in wall clock time is the only sign that the machine slept."""
+    clockmock.now.return_value = dt(2020, 5, 6, 4, 0)
+    scheduler = VortaScheduler()
+    reload_all = mocker.patch.object(scheduler, 'reload_all_timers')
+    scheduler.net_status = MagicMock()
+    scheduler.net_status.is_network_active.return_value = True
+    scheduler._net_up = False
+
+    clockmock.now.return_value = dt(2020, 5, 6, 6, 0)
+    scheduler.wake_timer.timeout.emit()
+
+    reload_all.assert_called_once()
+    assert scheduler._net_up is True
+
+
+def test_timely_wake_check_does_not_reschedule(mocker, clockmock):
+    """An on-time check must do nothing, or every profile gets rescheduled on every tick."""
+    clockmock.now.return_value = dt(2020, 5, 6, 4, 0)
+    scheduler = VortaScheduler()
+    reload_all = mocker.patch.object(scheduler, 'reload_all_timers')
+
+    clockmock.now.return_value = dt(2020, 5, 6, 4, 1)
+    scheduler.wake_timer.timeout.emit()
+
+    reload_all.assert_not_called()
+
+
+def test_logind_resume_signal_reloads_timers(mocker, clockmock):
+    """The logind fast path must survive the resume body moving into a helper."""
+    clockmock.now.return_value = dt(2020, 5, 6, 4, 0)
+    scheduler = VortaScheduler()
+    reload_all = mocker.patch.object(scheduler, 'reload_all_timers')
+    scheduler.net_status = MagicMock()
+
+    scheduler.loginSuspendNotify(True)
+    reload_all.assert_not_called()
+
+    scheduler.loginSuspendNotify(False)
+    reload_all.assert_called_once()