Mercurial > repos > borgend / changeset

--- 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):

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