# HG changeset patch # User Tuomo Valkonen # Date 1517826317 0 # Node ID a7bdc239ef6258d059dbe74e40e16acb541b28bc # Parent 55043f86c0b560a67c13a6e38b27bd529c87a5f1 Added exeption protection decorators to callbacks. If callbacks crash, there's rarely anything in the logs otherwise. diff -r 55043f86c0b5 -r a7bdc239ef62 borgend/backup.py --- 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: diff -r 55043f86c0b5 -r a7bdc239ef62 borgend/dreamtime.py --- 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()): diff -r 55043f86c0b5 -r a7bdc239ef62 borgend/exprotect.py --- /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 diff -r 55043f86c0b5 -r a7bdc239ef62 borgend/repository.py --- 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: diff -r 55043f86c0b5 -r a7bdc239ef62 borgend/scheduler.py --- 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: diff -r 55043f86c0b5 -r a7bdc239ef62 borgend/ui.py --- 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)