# HG changeset patch # User Tuomo Valkonen # Date 1517737135 0 # Node ID d33e2d7dbeb173716a2f5056980552804125d2d8 # Parent 32f2154ef25e4cc532e2a506e7566904c25228b0 Added some debug log messages diff -r 32f2154ef25e -r d33e2d7dbeb1 borgend/backup.py --- a/borgend/backup.py Sun Feb 04 02:19:26 2018 +0000 +++ b/borgend/backup.py Sun Feb 04 09:38:55 2018 +0000 @@ -34,6 +34,8 @@ QUEUED=3 ACTIVE=4 + def __str__(self): + return _statestring[self] class Errors(IntEnum): OK=0 @@ -57,6 +59,14 @@ Errors.ERRORS: 'errors' } +_statestring={ + State.INACTIVE: 'inactive', + State.PAUSED: 'paused', + State.SCHEDULED: 'scheduled', + State.QUEUED: 'queued', + State.ACTIVE: 'active' +} + class Operation: CREATE='create' PRUNE='prune' @@ -79,6 +89,12 @@ def add_error(self, error): self.errors=self.errors.combine(error) + def name(self): + if 'reason' in self.detail: + return str(self.type) + '.' + self.detail['reason'] + else: + return str(self.type) + class Status(Operation): def __init__(self, backup, op=None): @@ -447,9 +463,8 @@ # Update scheduled time to real starting time to schedule # next run relative to this self.current_operation.start_time=MonotonicTime.now() - self.state=State.ACTIVE # Reset error status when starting a new operation - self.__update_status() + self.__update_status(State.ACTIVE) t_log.start() t_res.start() @@ -577,31 +592,25 @@ if self._pause: self.logger.info("Waiting for resume to be signalled") - self.state=State.PAUSED - self.__update_status() + self.__update_status(State.PAUSED) self._cond.wait() else: if not self.scheduled_operation: op=self.__next_operation_unlocked() if op: - self.logger.info("Scheduling '%s' (detail: %s) on %s [%s]" % - (str(op.type), op.detail or 'none', - op.start_time.isoformat(), - op.start_time.__class__.__name__)) + self.scheduled_operation=op - self.scheduled_operation=op - self.state=State.SCHEDULED - self.__update_status() + self.__update_status(State.SCHEDULED) # Wait under scheduled wait - self.scheduler.wait_until(op.start_time, self._cond, self.backup_name) + eventname=op.name() + '@' + self.backup_name + self.scheduler.wait_until(op.start_time, self._cond, eventname) else: # Nothing scheduled - just wait self.logger.info("Waiting for manual scheduling") - self.state=State.INACTIVE - self.__update_status() + self.__update_status(State.INACTIVE) self._cond.wait() @@ -611,9 +620,9 @@ # available def __main_thread_queue_and_launch(self): if self.scheduled_operation: - self.logger.debug("Queuing") - self.state=State.QUEUED - self.__update_status() + + self.__update_status(State.QUEUED) + res=self.repository.queue_action(self._cond, action=self.__launch_and_wait, name=self.backup_name) @@ -711,7 +720,9 @@ return status, callback - def __update_status(self): + def __update_status(self, state): + self.logger.debug("Entering %s state", str(state)) + self.state=state status, callback = self.__status_unlocked() if callback: #self._cond.release() @@ -755,7 +766,7 @@ def is_paused(self): with self._cond: - paused=self.state==State.PAUSED + paused=(self.state==State.PAUSED) return paused def pause(self): diff -r 32f2154ef25e -r d33e2d7dbeb1 borgend/scheduler.py --- a/borgend/scheduler.py Sun Feb 04 02:19:26 2018 +0000 +++ b/borgend/scheduler.py Sun Feb 04 09:38:55 2018 +0000 @@ -151,36 +151,45 @@ logger.debug("Scheduler thread started") with self._cond: while not self._terminate: - snapshot = dreamtime.Snapshot() - now = snapshot.monotonic() - if not self._list: - timeout = None - else: - delta = self._list.when.horizon(snapshot)-now - if delta==math.inf: - timeout=None - else: - timeout = min(self.precision, delta) + try: + self.__schedule_one() + except: + logger.exception("Bug in scheduler") + + def __schedule_one(self): + snapshot = dreamtime.Snapshot() + now = snapshot.monotonic() + if not self._list: + timeout = None + delta = None + nextname = None + else: + nextname=self._list.name + delta = self._list.when.horizon(snapshot)-now + if delta==math.inf: + timeout=None + else: + timeout = min(self.precision, delta) - if not timeout or timeout>0: - logger.debug("Scheduler waiting %s seconds" % str(timeout)) - self._cond.wait(timeout) - snapshot = dreamtime.Snapshot() - now = snapshot.monotonic() - - logger.debug("Scheduler timed out") + if not timeout or timeout>0: + logger.debug("Scheduler waiting %s seconds [next event '%s' in %s seconds]" + % (str(timeout), nextname, str(delta))) + self._cond.wait(timeout) + snapshot = dreamtime.Snapshot() + now = snapshot.monotonic() + logger.debug("Scheduler timed out") - while self._list and self._list.when.horizon(snapshot) <= now: - ev=self._list - logger.debug("Scheduler activating %s" % (ev.name or "(unknown)")) - # We are only allowed to remove ev from list when ev.cond allows - self._unlink(ev) - # We need to release the lock on self._cond before acquire - # one ev.cond to avoid race conditions with self._wait - self._cond.release() - with ev.cond: - ev.cond.notify_all() - self._cond.acquire() + while self._list and self._list.when.horizon(snapshot) <= now: + ev=self._list + logger.debug("Scheduler activating %s" % (ev.name or "(unknown)")) + # We are only allowed to remove ev from list when ev.cond allows + self._unlink(ev) + # We need to release the lock on self._cond before acquire + # one ev.cond to avoid race conditions with self._wait + self._cond.release() + with ev.cond: + ev.cond.notify_all() + self._cond.acquire() def _sleepwake_callback(self, woke): @@ -211,7 +220,8 @@ # cond has to be acquired on entry! def wait_until(self, when, cond, name=None): - logger.debug("Scheduling '%s' in %s seconds [%s]" % - (name, when.seconds_to(), when.__class__.__name__)) + logger.info("Scheduling '%s' in %0.01f seconds / on %s [%s]" % + (name, when.seconds_to(), when.isoformat(), + when.__class__.__name__)) self._wait(ScheduledEvent(when, cond, name))