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.
This commit is contained in:
yfprojects 2022-02-20 06:04:12 +00:00 committed by GitHub
parent aacf438455
commit 4bbd091c59
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 344 additions and 67 deletions

View File

@ -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 @@ class VortaScheduler(QtCore.QObject):
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 @@ class VortaScheduler(QtCore.QObject):
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 @@ class VortaScheduler(QtCore.QObject):
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'

View File

@ -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,

View File

@ -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