Added exeption protection decorators to callbacks.

Mon, 05 Feb 2018 10:25:17 +0000

author
Tuomo Valkonen <tuomov@iki.fi>
date
Mon, 05 Feb 2018 10:25:17 +0000
changeset 106
a7bdc239ef62
parent 105
55043f86c0b5
child 107
f63835e9f29e

Added exeption protection decorators to callbacks.
If callbacks crash, there's rarely anything in the logs otherwise.

borgend/backup.py file | annotate | diff | comparison | revisions
borgend/dreamtime.py file | annotate | diff | comparison | revisions
borgend/exprotect.py file | annotate | diff | comparison | revisions
borgend/repository.py file | annotate | diff | comparison | revisions
borgend/scheduler.py file | annotate | diff | comparison | revisions
borgend/ui.py file | annotate | diff | comparison | revisions
--- a/borgend/backup.py	Sun Feb 04 14:37:09 2018 +0000
+++ b/borgend/backup.py	Mon Feb 05 10:25:17 2018 +0000
@@ -17,6 +17,7 @@
 from .dreamtime import MonotonicTime, DreamTime, RealTime
 from .instance import BorgInstance
 from .scheduler import TerminableThread
+from .exprotect import protect_noreturn
 
 _logger=logging.getLogger(__name__)
 
@@ -294,6 +295,7 @@
         running=self.is_running()
         assert(not running)
 
+    @protect_noreturn
     def __log_listener(self):
         self.logger.debug('Log listener thread waiting for entries')
         success=True
@@ -385,6 +387,7 @@
 
         self.logger.debug('Borg subprocess terminated; terminating log listener thread')
 
+    @protect_noreturn
     def __result_listener(self):
         self.logger.debug('Result listener thread waiting for result')
 
@@ -545,6 +548,7 @@
         self.thread_log=None
         self.borg_instance=None
 
+    @protect_noreturn
     def __main_thread(self):
         with self._cond:
             while not self._terminate:
--- a/borgend/dreamtime.py	Sun Feb 04 14:37:09 2018 +0000
+++ b/borgend/dreamtime.py	Mon Feb 05 10:25:17 2018 +0000
@@ -12,6 +12,8 @@
 import logging
 import math
 
+from .exprotect import protect_noreturn
+
 logger=logging.getLogger(__name__)
 
 _dreamtime_monitor=None
@@ -222,31 +224,27 @@
 
             return self
 
+        @protect_noreturn
         def handleSleepNotification_(self, aNotification):
             logger.info("System going to sleep")
-            try:
-                now=time.monotonic()
-                with self.__lock:
-                    self.__sleeptime=now
-                    callbacks=self.__callbacks.copy()
-                do_callbacks(callbacks, False)
-            except:
-                logger.exception("Bug in sleep handler")
+            now=time.monotonic()
+            with self.__lock:
+                self.__sleeptime=now
+                callbacks=self.__callbacks.copy()
+            do_callbacks(callbacks, False)
 
+        @protect_noreturn
         def handleWakeNotification_(self, aNotification):
             logger.info("System waking up from sleep")
-            try:
-                now=time.monotonic()
-                with self.__lock:
-                    if self.__sleeptime:
-                        slept=max(0, now-self.__sleeptime)
-                        logger.info("Slept %f seconds" % slept)
-                        self.__slept=self.__slept+slept
-                        self.__sleeptime=None
-                    callbacks=self.__callbacks.copy()
-                do_callbacks(callbacks, True)
-            except:
-                logger.exception("Bug in wakeup handler")
+            now=time.monotonic()
+            with self.__lock:
+                if self.__sleeptime:
+                    slept=max(0, now-self.__sleeptime)
+                    logger.info("Slept %f seconds" % slept)
+                    self.__slept=self.__slept+slept
+                    self.__sleeptime=None
+                callbacks=self.__callbacks.copy()
+            do_callbacks(callbacks, True)
 
         # Return dreamtime
         def dreamtime_sleeping(self, snapshot=Snapshot()):
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/borgend/exprotect.py	Mon Feb 05 10:25:17 2018 +0000
@@ -0,0 +1,31 @@
+#
+# Borgend by Tuomo Valkonen, 2018
+#
+# Except-catching decocators to catch bugs in callbacks
+#
+
+import logging
+
+logger=logging.getLogger(__name__)
+
+def protect_noreturn(fn):
+    name=fn.__name__
+    def wrapper(*args, **kwargs):
+        try:
+            fn(*args, **kwargs)
+        except:
+            logger.exception('bug in ' + name)
+    return wrapper
+
+
+def protect_return(default):
+    def wrap(fn):
+        name=fn.__name__
+        def wrapper(*args, **kwargs):
+            try:
+                return fn(*args, **kwargs)
+            except:
+                logger.exception('bug in ' + name)
+                return default
+        return wrapper
+    return wrap
--- a/borgend/repository.py	Sun Feb 04 14:37:09 2018 +0000
+++ b/borgend/repository.py	Mon Feb 05 10:25:17 2018 +0000
@@ -10,6 +10,7 @@
 
 from . import config
 from .scheduler import QueueThread, QueuedEvent
+from .exprotect import protect_noreturn
 
 logger=logging.getLogger(__name__)
 
@@ -29,6 +30,7 @@
     def __init__(self, **kwargs):
         super().__init__(target = self._fifo_thread, **kwargs)
 
+    @protect_noreturn
     def _fifo_thread(self):
         with self._cond:
             while not self._terminate:
--- a/borgend/scheduler.py	Sun Feb 04 14:37:09 2018 +0000
+++ b/borgend/scheduler.py	Mon Feb 05 10:25:17 2018 +0000
@@ -12,6 +12,7 @@
 from threading import Condition, Thread
 
 from . import dreamtime
+from .exprotect import protect_noreturn
 
 logger=logging.getLogger(__name__)
 
@@ -147,51 +148,46 @@
         super().__init__(target = self._scheduler_thread, name = 'Scheduler')
         dreamtime.add_callback(self, self._sleepwake_callback)
 
+    @protect_noreturn
     def _scheduler_thread(self):
         logger.debug("Scheduler thread started")
         with self._cond:
             while not self._terminate:
-                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)
+                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 [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")
+                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()
 
-
+    @protect_noreturn
     def _sleepwake_callback(self, woke):
         logger.debug("Rescheduling events after sleep/wakeup")
         with self._cond:
--- a/borgend/ui.py	Sun Feb 04 14:37:09 2018 +0000
+++ b/borgend/ui.py	Mon Feb 05 10:25:17 2018 +0000
@@ -15,6 +15,7 @@
 from . import dreamtime
 from . import branding
 from . import loggers
+from .exprotect import protect_noreturn
 from .config import settings
 
 logger=logging.getLogger(__name__)
@@ -83,26 +84,19 @@
 
 
 def progress_percentage(done, total, d):
-    progress=''
-    try:
-        percentage = 100*float(done)/float(total)
-        progress=': %d%%' % int(round(percentage))
-        if 'operation_no' in d:
-            progress=':#%d%s' % (d['operation_no'], progress)
-    except:
-        pass
+    percentage = 100*float(done)/float(total)
+    progress=': %d%%' % int(round(percentage))
+    if 'operation_no' in d:
+        progress=':#%d%s' % (d['operation_no'], progress)
     return progress
 
 def progress_parts(done, total, d):
-    progress=''
-    try:
-        progress=': %d/%d' % (int(done), int(total))
-        if 'operation_no' in d:
-            progress=':#%d%s' % (d['operation_no'], progress)
-    except:
-        pass
+    progress=': %d/%d' % (int(done), int(total))
+    if 'operation_no' in d:
+        progress=':#%d%s' % (d['operation_no'], progress)
     return progress
 
+_error_state=(backup.State.INACTIVE, backup.Errors.ERRORS)
 
 def make_title(status):
     def add_info(info, new):
@@ -282,6 +276,9 @@
 
         return menu, title
 
+    # Callbacks -- exception-protected to get any indications of errors
+
+    @protect_noreturn
     def refresh_ui(self):
         with self.lock:
             menu, title=self.build_menu_and_timer()
@@ -289,6 +286,7 @@
             self.menu.update(menu)
             self.title=title
 
+    @protect_noreturn
     def __status_callback(self, index, status, errorlog=None):
         logger.debug("Tray status callback")
         with self.lock:
@@ -314,10 +312,7 @@
             notification_workaround(branding.appname_stylised,
                                     msgid, errorlog['message'])
 
-    def __sleepwake_callback(self, woke):
-        if woke:
-            self.refresh_ui()
-
+    @protect_noreturn
     def pause_resume_all(self):
         with self.lock:
             try:
@@ -335,9 +330,16 @@
             except:
                 logger.exception("Pause/resume error")
 
+    @protect_noreturn
+    def __sleepwake_callback(self, woke):
+        if woke:
+            self.refresh_ui()
+
+    @protect_noreturn
     def quit(self):
         rumps.quit_application()
 
+    @protect_noreturn
     def __menu_select_backup(self, sender, b):
         #sender.state=not sender.state
         logger.debug("Manually backup '%s'", b.name)

mercurial