From 4bbd091c59e36bb77effe69d417a86ce16012cea Mon Sep 17 00:00:00 2001
From: yfprojects <62463991+real-yfprojects@users.noreply.github.com>
Date: Sun, 20 Feb 2022 06:04:12 +0000
Subject: [PATCH] Rewrite scheduler logic. By @real-yfprojects (#1204)

The scheduler now will react to a new fixed time also if 24h haven't passed yet.
All in all the code is supposed to be cleaner and easier understandable.
The logging was slightly modified.
---
 src/vorta/scheduler.py  | 155 +++++++++++++++----------
 tests/conftest.py       |  11 +-
 tests/test_scheduler.py | 245 +++++++++++++++++++++++++++++++++++++++-
 3 files changed, 344 insertions(+), 67 deletions(-)

diff --git a/src/vorta/scheduler.py b/src/vorta/scheduler.py
index c8efb9e0..99d4f66f 100644
--- a/src/vorta/scheduler.py
+++ b/src/vorta/scheduler.py
@@ -1,8 +1,8 @@
 import logging
 import threading
-from datetime import date
 from datetime import datetime as dt
 from datetime import timedelta
+from typing import Dict, Union
 
 from PyQt5 import QtCore
 from PyQt5.QtWidgets import QApplication
@@ -25,7 +25,10 @@ class VortaScheduler(QtCore.QObject):
 
     def __init__(self):
         super().__init__()
-        self.timers = dict()  # keep mapping of profiles to timers
+
+        #: mapping of profiles to timers
+        self.timers: Dict[int, Dict[str, Union[QtCore.QTimer, dt]]] = dict()
+
         self.app = QApplication.instance()
         self.lock = threading.Lock()
 
@@ -40,7 +43,7 @@ def tr(self, *args, **kwargs):
         scope = self.__class__.__name__
         return translate(scope, *args, **kwargs)
 
-    def set_timer_for_profile(self, profile_id):
+    def set_timer_for_profile(self, profile_id: int):
         """
         Set a timer for next scheduled backup run of this profile.
 
@@ -56,71 +59,107 @@ def set_timer_for_profile(self, profile_id):
         if profile is None:  # profile doesn't exist any more.
             return
 
-        # First stop and remove any existing timer for this profile
-        self.lock.acquire()
-        if profile_id in self.timers:
-            self.remove_job(profile_id)
+        with self.lock:  # Acquire lock
 
-        # If no repo is set or only manual backups, just return without
-        # replacing the job we removed above.
-        if profile.repo is None or profile.schedule_mode == 'off':
-            logger.debug('Scheduler for profile %s is disabled.', profile_id)
-            self.lock.release()
-            return
+            if profile_id in self.timers:
+                self.remove_job(profile_id)  # reset schedule
 
-        logger.info('Setting timer for profile %s', profile_id)
+            if profile.repo is None:  # No backups without repo set
+                logger.debug(
+                    'Nothing scheduled for profile %s because of unset repo.',
+                    profile_id)
 
-        last_run_log = EventLogModel.select().where(
-            EventLogModel.subcommand == 'create',
-            EventLogModel.category == 'scheduled',
-            EventLogModel.profile == profile.id,
-            0 <= EventLogModel.returncode <= 1,
-        ).order_by(EventLogModel.end_time.desc()).first()
+            if profile.schedule_mode == 'off':
+                logger.debug('Scheduler for profile %s is disabled.', profile_id)
+                return
 
-        # Desired interval between scheduled backups. Uses datetime.timedelta() units.
-        if profile.schedule_mode == 'interval':
-            interval = {profile.schedule_interval_unit: profile.schedule_interval_count}
-        elif profile.schedule_mode == 'fixed':
-            interval = {'days': 1}
+            logger.info('Setting timer for profile %s', profile_id)
 
-        # If last run was too long ago and catch-up is enabled, run now
-        if profile.schedule_make_up_missed \
-                and last_run_log is not None \
-                and last_run_log.end_time + timedelta(**interval) < dt.now():
-            logger.debug('Catching up by running job for %s', profile.name)
-            self.lock.release()
-            self.create_backup(profile.id)
-            return
+            # determine last backup time
+            last_run_log = EventLogModel.select().where(
+                EventLogModel.subcommand == 'create',
+                EventLogModel.category == 'scheduled',
+                EventLogModel.profile == profile.id,
+                0 <= EventLogModel.returncode <= 1,
+            ).order_by(EventLogModel.end_time.desc()).first()
 
-        # If the job never ran, use midnight as random starting point
-        if last_run_log is None:
-            last_run = dt.now().replace(hour=0, minute=0)
-        else:
-            last_run = last_run_log.end_time
+            if last_run_log is None:
+                # look for non scheduled (manual) backup runs
+                last_run_log = EventLogModel.select().where(
+                    EventLogModel.subcommand == 'create',
+                    EventLogModel.profile == profile.id,
+                    0 <= EventLogModel.returncode <= 1,
+                ).order_by(EventLogModel.end_time.desc()).first()
 
-        # Squash seconds to get nice starting time
-        last_run = last_run.replace(second=0, microsecond=0)
+            # calculate next scheduled time
+            if profile.schedule_mode == 'interval':
+                if last_run_log is None:
+                    last_time = dt.now()
+                else:
+                    last_time = last_run_log.end_time
 
-        # Fixed time is a special case of days=1 interval
-        if profile.schedule_mode == 'fixed':
-            last_run = last_run.replace(hour=profile.schedule_fixed_hour, minute=profile.schedule_fixed_minute)
+                interval = {profile.schedule_interval_unit: profile.schedule_interval_count}
+                next_time = last_time + timedelta(**interval)
 
-        # Add interval to last run time to arrive at next run.
-        next_run = last_run
-        now = dt.now()
-        while next_run < now:
-            next_run += timedelta(**interval)
+            elif profile.schedule_mode == 'fixed':
+                if last_run_log is None:
+                    last_time = dt.now()
+                else:
+                    last_time = last_run_log.end_time + timedelta(days=1)
 
-        logger.debug('Scheduling next run for %s', next_run)
-        timer_ms = (next_run - dt.now()).total_seconds() * 1000
-        timer = QtCore.QTimer()
-        timer.setSingleShot(True)
-        timer.setInterval(int(timer_ms))
-        timer.timeout.connect(lambda: self.create_backup(profile_id))
-        timer.start()
-        self.timers[profile_id] = {'qtt': timer, 'dt': next_run}
+                next_time = last_time.replace(
+                    hour=profile.schedule_fixed_hour,
+                    minute=profile.schedule_fixed_minute)
 
-        self.lock.release()
+            else:
+                # unknown schedule mode
+                raise ValueError(
+                    "Unknown schedule mode '{}'".format(profile.schedule_mode))
+
+            # handle missing of a scheduled time
+            if next_time <= dt.now():
+
+                if profile.schedule_make_up_missed:
+                    self.lock.release()
+                    try:
+                        logger.debug('Catching up by running job for %s (%s)',
+                                     profile.name, profile_id)
+                        self.create_backup(profile_id)
+                    finally:
+                        self.lock.acquire()  # with-statement will try to release
+
+                    return  # create_backup will lead to a call to this method
+
+                # calculate next time from now
+                if profile.schedule_mode == 'interval':
+                    # next_time % interval should be 0
+                    # while next_time > now
+                    delta = dt.now() - last_time
+                    next_time = dt.now() - delta % timedelta(**interval)
+                    next_time += timedelta(**interval)
+
+                elif profile.schedule_mode == 'fixed':
+                    if next_time.date() == dt.now().date():
+                        # time for today has passed, schedule for tomorrow
+                        next_time += timedelta(days=1)
+                    else:
+                        # schedule for today
+                        next_time = dt.now().replace(
+                            hour=profile.schedule_fixed_hour,
+                            minute=profile.schedule_fixed_minute)
+
+            # start QTimer
+            logger.debug('Scheduling next run for %s', next_time)
+
+            timer_ms = (next_time - dt.now()).total_seconds() * 1000
+
+            timer = QtCore.QTimer()
+            timer.setSingleShot(True)
+            timer.setInterval(int(timer_ms))
+            timer.timeout.connect(lambda: self.create_backup(profile_id))
+            timer.start()
+
+            self.timers[profile_id] = {'qtt': timer, 'dt': next_time}
 
         # Emit signal so that e.g. the GUI can react to the new schedule
         self.schedule_changed.emit(profile_id)
@@ -220,7 +259,7 @@ def post_backup_tasks(self, profile_id):
                     job = BorgListRepoJob(msg['cmd'], msg, profile.repo.id)
                     self.app.jobs_manager.add_job(job)
 
-        validation_cutoff = date.today() - timedelta(days=7 * profile.validation_weeks)
+        validation_cutoff = dt.now() - timedelta(days=7 * profile.validation_weeks)
         recent_validations = EventLogModel.select().where(
             (
                 EventLogModel.subcommand == 'check'
diff --git a/tests/conftest.py b/tests/conftest.py
index 5ec6c834..3fbde4aa 100644
--- a/tests/conftest.py
+++ b/tests/conftest.py
@@ -1,15 +1,18 @@
 import os
-from peewee import SqliteDatabase
-import pytest
 import sys
 from datetime import datetime as dt
 from unittest.mock import MagicMock
 
+import pytest
+from peewee import SqliteDatabase
+
 import vorta
 import vorta.application
 import vorta.borg.jobs_manager
-from vorta.store.models import RepoModel, RepoPassword, BackupProfileModel, SourceFileModel, \
-    SettingsModel, ArchiveModel, WifiSettingModel, EventLogModel, SchemaVersion
+from vorta.store.models import (ArchiveModel, BackupProfileModel,
+                                EventLogModel, RepoModel, RepoPassword,
+                                SchemaVersion, SettingsModel, SourceFileModel,
+                                WifiSettingModel)
 from vorta.views.main_window import MainWindow
 
 models = [RepoModel, RepoPassword, BackupProfileModel, SourceFileModel,
diff --git a/tests/test_scheduler.py b/tests/test_scheduler.py
index 48e8f8d4..6c3152bb 100644
--- a/tests/test_scheduler.py
+++ b/tests/test_scheduler.py
@@ -1,15 +1,250 @@
+from datetime import datetime as dt
+from datetime import timedelta as td
+from functools import wraps
+from unittest.mock import MagicMock
+
 import pytest
+from pytest import mark
+
 import vorta.borg
-from vorta.store.models import EventLogModel
+import vorta.scheduler
+from vorta.scheduler import VortaScheduler
+from vorta.store.models import BackupProfileModel, EventLogModel
+
+PROFILE_NAME = 'Default'
+FIXED_SCHEDULE = 'fixed'
+INTERVAL_SCHEDULE = 'interval'
+MANUAL_SCHEDULE = 'off'
 
 
+@pytest.fixture
+def clockmock(monkeypatch):
+    datetime_mock = MagicMock(wraps=dt)
+    monkeypatch.setattr(vorta.scheduler, "dt", datetime_mock)
+
+    return datetime_mock
+
+
+def prepare(func):
+    """Decorator adding common preparation steps."""
+    @wraps(func)
+    def do(qapp, qtbot, mocker, borg_json_output):
+        stdout, stderr = borg_json_output('create')
+        popen_result = mocker.MagicMock(stdout=stdout,
+                                        stderr=stderr,
+                                        returncode=0)
+        mocker.patch.object(vorta.borg.borg_job,
+                            'Popen',
+                            return_value=popen_result)
+
+        return func(qapp, qtbot, mocker, borg_json_output)
+
+    return do
+
+
+@prepare
 def test_scheduler_create_backup(qapp, qtbot, mocker, borg_json_output):
+    """Test running a backup with `create_backup`."""
     events_before = EventLogModel.select().count()
-    stdout, stderr = borg_json_output('create')
-    popen_result = mocker.MagicMock(stdout=stdout, stderr=stderr, returncode=0)
-    mocker.patch.object(vorta.borg.borg_job, 'Popen', return_value=popen_result)
 
     with qtbot.waitSignal(qapp.backup_finished_event, **pytest._wait_defaults):
         qapp.scheduler.create_backup(1)
 
-    assert EventLogModel.select().where(EventLogModel.returncode == 0).count() == events_before + 1
+    assert EventLogModel.select().where(
+        EventLogModel.returncode == 0).count() == events_before + 1
+
+
+def test_manual_mode():
+    """Test scheduling in manual mode."""
+    scheduler = VortaScheduler()
+
+    # setup model
+    profile = BackupProfileModel.get(name=PROFILE_NAME)
+    profile.schedule_make_up_missed = False
+    profile.schedule_mode = MANUAL_SCHEDULE
+    profile.save()
+
+    # test
+    scheduler.set_timer_for_profile(profile.id)
+    assert len(scheduler.timers) == 0
+
+
+def test_simple_schedule(clockmock):
+    """Test a simple scheduling including `next_job` and `remove_job`."""
+    scheduler = VortaScheduler()
+
+    # setup
+    clockmock.now.return_value = dt(2020, 5, 6, 4, 30)
+
+    profile = BackupProfileModel.get(name=PROFILE_NAME)
+    profile.schedule_make_up_missed = False
+    profile.schedule_mode = INTERVAL_SCHEDULE
+    profile.schedule_interval_unit = 'hours'
+    profile.schedule_interval_count = 3
+    profile.save()
+
+    # test set timer and next_job
+    scheduler.set_timer_for_profile(profile.id)
+    assert len(scheduler.timers) == 1
+    assert scheduler.next_job() == '07:30 ({})'.format(PROFILE_NAME)
+    assert scheduler.next_job_for_profile(profile.id) == '2020-05-06 07:30'
+
+    # test remove_job and next_job
+    scheduler.remove_job(profile.id)
+    assert len(scheduler.timers) == 0
+    assert scheduler.next_job() == 'None scheduled'
+    assert scheduler.next_job_for_profile(profile.id) == 'None scheduled'
+
+
+@mark.parametrize("scheduled", [True, False])
+@mark.parametrize(
+    "passed_time, now, unit, count, added_time",
+    [
+        # simple
+        (td(), td(hours=4, minutes=30), 'hours', 3, td(hours=3)),
+
+        # next day
+        (td(), td(hours=4, minutes=30), 'hours', 20, td(hours=20)),
+
+        # passed by less than interval
+        (td(hours=2), td(hours=4, minutes=30), 'hours', 3, td(hours=1)),
+
+        # passed by exactly interval
+        (td(hours=3), td(hours=4, minutes=30), 'hours', 3, td(hours=3)),
+
+        # passed by multiple times the interval
+        (td(hours=7), td(hours=4, minutes=30), 'hours', 3, td(hours=2))
+    ])
+def test_interval(clockmock, passed_time, scheduled, now, unit, count,
+                  added_time):
+    """Test scheduling in interval mode."""
+    # setup
+    scheduler = VortaScheduler()
+
+    time = dt(2020, 5, 4, 0, 0) + now
+    clockmock.now.return_value = time
+
+    profile = BackupProfileModel.get(name=PROFILE_NAME)
+    profile.schedule_make_up_missed = False
+    profile.schedule_mode = INTERVAL_SCHEDULE
+    profile.schedule_interval_unit = unit
+    profile.schedule_interval_count = count
+    profile.save()
+
+    event = EventLogModel(subcommand='create',
+                          profile=profile.id,
+                          returncode=0,
+                          category='scheduled' if scheduled else '',
+                          start_time=time - passed_time,
+                          end_time=time - passed_time)
+    event.save()
+
+    # run test
+    scheduler.set_timer_for_profile(profile.id)
+    assert scheduler.timers[profile.id]['dt'] == time + added_time
+
+
+@mark.parametrize(
+    "now, unit, count, added_time",
+    [
+        # simple
+        (td(hours=4, minutes=30), 'hours', 3, td(hours=3)),
+
+        # next day
+        (td(hours=4, minutes=30), 'hours', 20, td(hours=20)),
+    ])
+def test_first_interval(clockmock, now, unit, count, added_time):
+    """Test scheduling in interval mode without a previous backup."""
+    # setup
+    scheduler = VortaScheduler()
+
+    time = dt(2020, 5, 4, 0, 0) + now
+    clockmock.now.return_value = time
+
+    profile = BackupProfileModel.get(name=PROFILE_NAME)
+    profile.schedule_make_up_missed = False
+    profile.schedule_mode = INTERVAL_SCHEDULE
+    profile.schedule_interval_unit = unit
+    profile.schedule_interval_count = count
+    profile.save()
+
+    # run test
+    scheduler.set_timer_for_profile(profile.id)
+    assert scheduler.timers[profile.id]['dt'] == time + added_time
+
+
+@mark.parametrize("scheduled", [True, False])
+@mark.parametrize(
+    "passed_time",
+    [td(hours=0), td(hours=5),
+     td(hours=14), td(hours=27)])
+@mark.parametrize(
+    "now, hour, minute",
+    [
+        # same day
+        (td(hours=4, minutes=30), 15, 00),
+
+        # next day
+        (td(hours=4, minutes=30), 3, 30),
+    ])
+def test_fixed(clockmock, passed_time, scheduled, now, hour, minute):
+    """Test scheduling in fixed mode."""
+    # setup
+    scheduler = VortaScheduler()
+
+    time = dt(2020, 5, 4, 0, 0) + now
+    clockmock.now.return_value = time
+
+    profile = BackupProfileModel.get(name=PROFILE_NAME)
+    profile.schedule_make_up_missed = False
+    profile.schedule_mode = FIXED_SCHEDULE
+    profile.schedule_fixed_hour = hour
+    profile.schedule_fixed_minute = minute
+    profile.save()
+
+    last_time = time - passed_time
+    event = EventLogModel(subcommand='create',
+                          profile=profile.id,
+                          returncode=0,
+                          category='scheduled' if scheduled else '',
+                          start_time=last_time,
+                          end_time=last_time)
+    event.save()
+
+    # run test
+    expected = time.replace(hour=hour, minute=minute)
+
+    if time >= expected or last_time.date() == expected.date():
+        expected += td(days=1)
+
+    scheduler.set_timer_for_profile(profile.id)
+    assert scheduler.timers[profile.id]['dt'] == expected
+
+
+@mark.parametrize(
+    "now, hour, minute, added_time",
+    [
+        # same day
+        (td(hours=4, minutes=30), 15, 00, td(hours=10, minutes=30)),
+
+        # next day
+        (td(hours=4, minutes=30), 3, 30, td(hours=23)),
+    ])
+def test_first_fixed(clockmock, now, hour, minute, added_time):
+    """Test scheduling in fixed mode without a previous backup."""
+    # setup
+    scheduler = VortaScheduler()
+
+    time = dt(2020, 5, 4, 0, 0) + now
+    clockmock.now.return_value = time
+
+    profile = BackupProfileModel.get(name=PROFILE_NAME)
+    profile.schedule_make_up_missed = False
+    profile.schedule_mode = FIXED_SCHEDULE
+    profile.schedule_fixed_hour = hour
+    profile.schedule_fixed_minute = minute
+    profile.save()
+
+    # run test
+    scheduler.set_timer_for_profile(profile.id)
+    assert scheduler.timers[profile.id]['dt'] == time + added_time