Further improvements to state reporting; indicate busyness if repository lock cannot be acquired

Sun, 21 Jan 2018 23:52:35 +0000

author
Tuomo Valkonen <tuomov@iki.fi>
date
Sun, 21 Jan 2018 23:52:35 +0000
changeset 45
aa2a95dc6093
parent 44
ac449729a896
child 46
ecb41072a1b7

Further improvements to state reporting; indicate busyness if repository lock cannot be acquired

backup.py file | annotate | diff | comparison | revisions
borgend.py file | annotate | diff | comparison | revisions
ui.py file | annotate | diff | comparison | revisions
--- 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())
--- 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
--- 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)

mercurial