# HG changeset patch # User Tuomo Valkonen # Date 1516578755 0 # Node ID aa2a95dc6093d712fb7be049b611b387e7346eb8 # Parent ac449729a89686e16be84107ea1d1fe6e26cbfed Further improvements to state reporting; indicate busyness if repository lock cannot be acquired diff -r ac449729a896 -r aa2a95dc6093 backup.py --- a/backup.py Sun Jan 21 22:46:05 2018 +0000 +++ b/backup.py Sun Jan 21 23:52:35 2018 +0000 @@ -13,6 +13,17 @@ logger=borgend.logger.getChild(__name__) +# State +INACTIVE=0 +SCHEDULED=1 +ACTIVE=2 +BUSY=3 +OFFLINE=4 +ERRORS=5 + +def combine_state(state1, state2): + return max(state1, state2) + loglevel_translation={ 'CRITICAL': logging.CRITICAL, 'ERROR': logging.ERROR, @@ -111,7 +122,6 @@ self.config=config self.lastrun_when=None - self.lastrun_errors=None self.borg_instance=None self.current_operation=None self.thread_log=None @@ -120,6 +130,7 @@ self.scheduled_operation=None self.lock=Lock() self.__status_update_callback=None + self.state=INACTIVE def is_running(self): with self.lock: @@ -185,8 +196,14 @@ logger.log(lvl, status['name'] + ': ' + status['message']) if lvl>=logging.WARNING: errors_this_message=status + state=ERRORS + if ('msgid' in status and + (status['msgid']=='LockTimeout' or # observed in reality + status['msgid']=='LockErrorT' or # in docs + status['msgid']=='LockErrorT')): # in docs + state=BUSY with self.lock: - self.current_operation['errors']=True + self.state=combine_state(self.state, state) status, callback=self.__status_unlocked() else: logger.debug('Unrecognised log entry %s' % str(status)) @@ -210,30 +227,39 @@ res=self.borg_instance.read_result() - errors=False + # Finish processing remaining errors + self.thread_log.join() + + with self.lock: + state=self.state + + # If there were no errors, reset back to INACTIVE state + if state==ACTIVE: + state=INACTIVE logger.debug('Borg result: %s' % str(res)) - if res is None: - errors=True + if res is None and state==INACTIVE: + logger.error('No result from borg despite no error in log') + state=ERRORS logger.debug('Waiting for borg subprocess to terminate in result thread') - errors=errors or not self.borg_instance.wait() + if not self.borg_instance.wait(): + logger.critical('Borg subprocess did not terminate') + state=combine_state(state, ERRORS) - logger.debug('Borg subprocess terminated (errors: %s); terminating result listener thread' % str(errors)) - - self.thread_log.join() + logger.debug('Borg subprocess terminated (end state %s); terminating result listener thread' % str(state)) with self.lock: if self.current_operation['operation']=='create': self.lastrun_when=self.current_operation['when_monotonic'] - self.lastrun_errors=errors self.thread_res=None self.thread_log=None self.borg_instance=None self.current_operation=None self.__schedule_unlocked() + self.state=state status, callback=self.__status_unlocked() if callback: callback(self, status) @@ -258,6 +284,7 @@ self.queue=queue self.current_operation=op self.current_operation['when_monotonic']=time.monotonic() + self.state=ACTIVE t_log.start() t_res.start() @@ -294,7 +321,7 @@ except Exception as err: logger.debug('Rescheduling after failure') self.lastrun_when=time.monotonic() - self.lastrun_errors=True + self.state=ERRORS self.__schedule_unlocked() raise err @@ -369,7 +396,7 @@ return {'operation': 'create', 'detail': 'initial', 'when_monotonic': now+initial_interval} - elif self.lastrun_errors: + elif self.state>=BUSY: if self.retry_interval==0: return None else: @@ -398,6 +425,7 @@ tmr=Timer(delay, self.__queue_timed_operation) self.scheduled_operation=op self.timer=tmr + self.state=combine_state(self.state, SCHEDULED) tmr.start() return op @@ -425,17 +453,12 @@ else: status={'type': 'nothing'} - if self.lastrun_errors is not None: - status['errors']=self.lastrun_errors + status['name']=self.name + status['state']=self.state if 'detail' not in status: status['detail']='NONE' - if 'errors' not in status: - status['errors']=False - - status['name']=self.name - if 'when_monotonic' in status: status['when']=(status['when_monotonic'] -time.monotonic()+time.time()) diff -r ac449729a896 -r aa2a95dc6093 borgend.py --- a/borgend.py Sun Jan 21 22:46:05 2018 +0000 +++ b/borgend.py Sun Jan 21 23:52:35 2018 +0000 @@ -1,10 +1,12 @@ #!/usr/local/bin/python3 import os +import sys import logging import logging.handlers import argparse import platform +import utils from fifolog import FIFOHandler # @@ -98,6 +100,7 @@ except Exception as err: utils.log_exception(logger, err, detail='Exiting') logging.shutdown() + os.exit() # # This shit is fucked, disables ^C etc., and threading doesn't seem to help diff -r ac449729a896 -r aa2a95dc6093 ui.py --- a/ui.py Sun Jan 21 22:46:05 2018 +0000 +++ b/ui.py Sun Jan 21 23:52:35 2018 +0000 @@ -8,32 +8,34 @@ import logging import borgend import utils +import backup from threading import Lock, Timer from config import settings import objc logger=borgend.logger.getChild(__name__) -INACTIVE=0 -SCHEDULED_OK=1 -ACTIVE=2 -OFFLINE=3 -ERRORS=4 +traynames={ + backup.INACTIVE: 'B.', + backup.SCHEDULED: 'B.', + backup.ACTIVE: 'B!', + backup.BUSY: 'B⦙', + backup.OFFLINE: 'B⦙', + backup.ERRORS: 'B?' +} -traynames={ - INACTIVE: 'B.', - SCHEDULED_OK: 'B.', - ACTIVE: 'B!', - OFFLINE: 'B⦙', - ERRORS: 'B?' +statestring={ + backup.INACTIVE: 'inactive', + backup.SCHEDULED: 'scheduled', + backup.ACTIVE: 'active', + backup.BUSY: 'busy', + backup.OFFLINE: 'offline', + backup.ERRORS: 'errors' } # Refresh the menu at most once a second to reduce flicker refresh_interval=1.0 -def combine_state(state1, state2): - return max(state1, state2) - # Workaround to rumps brokenness; # see https://github.com/jaredks/rumps/issues/59 def notification_workaround(title, subtitle, message): @@ -68,8 +70,7 @@ return '{0:.2f}TB'.format(B/TB) def make_title(status): - state=INACTIVE - + state=status['state'] if status['type']=='scheduled': # Operation scheduled when=status['when'] @@ -88,13 +89,11 @@ twhen=time.localtime(when+30) whenstr='at %02d:%02d' % (twhen.tm_hour, twhen.tm_min) - if status['detail']=='normal': - state=SCHEDULED_OK - detail='' - else: - if status['detail']=='retry': - state=ERRORS - detail=status['detail']+' ' + detail='' + if state>=backup.BUSY and state in statestring: + detail=statestring[state] + '; ' + if status['detail']!='normal': + detail=detail+status['detail']+' ' title="%s (%s%s %s)" % (status['name'], detail, status['operation'], whenstr) elif status['type']=='current': # Operation running @@ -105,15 +104,12 @@ progress=' %s→%s' % (humanbytes(status['original_size']), humanbytes(status['deduplicated_size'])) title="%s (running: %s%s)" % (status['name'], status['operation'], progress) - state=ACTIVE else: # status['type']=='nothing': # Should be unscheduled, nothing running - title=status['name'] - if status['errors']: - title=title + " (errors)" - - if status['errors']: - state=ERRORS + detail='' + if state>=backup.BUSY and state in statestring: + detail=' (' + statestring[state] + ')' + title=status['name'] + detail return title, state @@ -147,7 +143,7 @@ def __rebuild_menu(self): menu=[] - state=INACTIVE + state=backup.INACTIVE for index in range(len(self.backups)): b=self.backups[index] title, this_state=make_title(self.statuses[index]) @@ -156,12 +152,12 @@ # fixes this brain damage cbm=lambda sender, _b=b: self.__menu_select_backup(sender, _b) item=rumps.MenuItem(title, callback=cbm) - if this_state==SCHEDULED_OK: + if this_state==backup.SCHEDULED: item.state=1 - elif this_state>=OFFLINE: + elif this_state>=backup.BUSY: item.state=-1 menu.append(item) - state=combine_state(state, this_state) + state=backup.combine_state(state, this_state) menu_log=rumps.MenuItem("Show log", callback=lambda _: showlog()) menu.append(menu_log)