# HG changeset patch # User Tuomo Valkonen # Date 1516541652 0 # Node ID b4b4bb7a2ec5c3237848bf873c89a145185961a2 # Parent 3dd525652dc814012a9dfd119e34547f7d516eca More logging detail diff -r 3dd525652dc8 -r b4b4bb7a2ec5 backup.py --- a/backup.py Sun Jan 21 12:10:57 2018 +0000 +++ b/backup.py Sun Jan 21 13:34:12 2018 +0000 @@ -10,6 +10,8 @@ from queue import Queue from threading import Thread, Lock, Timer +logger=logging.getLogger(__name__) + loglevel_translation={ 'CRITICAL': logging.CRITICAL, 'ERROR': logging.ERROR, @@ -122,10 +124,10 @@ assert(not running) def __log_listener(self): - logging.debug('Log listener thread waiting for entries') + logger.debug('Log listener thread waiting for entries') success=True for status in iter(self.borg_instance.read_log, None): - logging.debug(str(status)) + logger.debug(str(status)) t=status['type'] errors_this_message=None @@ -165,23 +167,23 @@ if 'name' not in status: status['name']='borg' lvl=translate_loglevel(status['levelname']) - logging.log(lvl, status['name'] + ': ' + status['message']) + logger.log(lvl, status['name'] + ': ' + status['message']) if lvl>=logging.WARNING: errors_this_message=status with self.lock: self.current_operation['errors']=True status, callback=self.__status_unlocked() else: - logging.debug('Unrecognised log entry %s' % str(status)) + logger.debug('Unrecognised log entry %s' % str(status)) if callback: callback(self, status, errors=errors_this_message) - logging.debug('Waiting for borg subprocess to terminate in log thread') + logger.debug('Waiting for borg subprocess to terminate in log thread') self.borg_instance.wait() - logging.debug('Borg subprocess terminated; terminating log listener thread') + logger.debug('Borg subprocess terminated; terminating log listener thread') def __result_listener(self): with self.lock: @@ -189,22 +191,22 @@ if callback: callback(self, status) - logging.debug('Result listener thread waiting for result') + logger.debug('Result listener thread waiting for result') res=self.borg_instance.read_result() success=True - logging.debug('Borg result: %s' % str(res)) + logger.debug('Borg result: %s' % str(res)) if res==None: success=False - logging.debug('Waiting for borg subprocess to terminate in result thread') + logger.debug('Waiting for borg subprocess to terminate in result thread') success=success and self.borg_instance.wait() - logging.debug('Borg subprocess terminated (success: %s); terminating result listener thread' % str(success)) + logger.debug('Borg subprocess terminated (success: %s); terminating result listener thread' % str(success)) self.thread_log.join() @@ -227,6 +229,8 @@ inst=BorgInstance(op['operation'], archive_or_repository, *args) inst.launch(passphrase=self.__passphrase) + logger.debug('Creating listener threads') + t_log=Thread(target=self.__log_listener) t_log.daemon=True @@ -250,11 +254,11 @@ return False else: if self.timer: - logging.debug('Unscheduling timed operation due to launch of operation') + logger.debug('Unscheduling timed operation due to launch of operation') self.timer=None self.scheduled_operation=None - logging.debug("Launching '%s' on '%s'" % (op['operation'], self.name)) + logger.debug("Launching '%s' on '%s'" % (op['operation'], self.name)) if op['operation']=='create': archive="%s::%s%s" % (self.repository, @@ -270,7 +274,7 @@ self.common_parameters + self.prune_parameters)) else: - logging.error("Invalid operaton '%s'" % op['operation']) + logger.error("Invalid operaton '%s'" % op['operation']) self.__schedule_unlocked() return True @@ -303,7 +307,7 @@ def join(self): - logging.debug('Waiting for borg listener threads to terminate') + logger.debug('Waiting for borg listener threads to terminate') with self.lock: thread_log=self.thread_log diff -r 3dd525652dc8 -r b4b4bb7a2ec5 borgend.py --- a/borgend.py Sun Jan 21 12:10:57 2018 +0000 +++ b/borgend.py Sun Jan 21 13:34:12 2018 +0000 @@ -4,9 +4,11 @@ from threading import Thread logging.basicConfig(#filename='example.log', - format='%(levelname)s:%(message)s', + #format='%(levelname)s:%(message)s', level=logging.DEBUG) +logger=logging.getLogger(__name__) + from backup import Backup from config import settings from queue import Queue @@ -17,7 +19,7 @@ backups=[None]*len(backupconfigs); for i in range(len(backupconfigs)): - logging.info('Setting up backup set %d' % i) + logger.info('Setting up backup set %d' % i) backups[i]=Backup(i, backupconfigs[i]) backups[i].schedule() diff -r 3dd525652dc8 -r b4b4bb7a2ec5 config.py --- a/config.py Sun Jan 21 12:10:57 2018 +0000 +++ b/config.py Sun Jan 21 13:34:12 2018 +0000 @@ -11,6 +11,8 @@ import logging from functools import reduce +logger=logging.getLogger(__name__) + # # Defaults # @@ -124,7 +126,7 @@ cfgfile=os.path.join(xdg.XDG_CONFIG_HOME, "borgend", "config.yaml") -logging.info("Reading configuration file %s" % cfgfile) +logger.info("Reading configuration file %s" % cfgfile) if not (os.path.exists(cfgfile) and os.path.isfile(cfgfile)): raise SystemExit('Configuration file required: {cfgfile}') diff -r 3dd525652dc8 -r b4b4bb7a2ec5 instance.py --- a/instance.py Sun Jan 21 12:10:57 2018 +0000 +++ b/instance.py Sun Jan 21 13:34:12 2018 +0000 @@ -8,6 +8,8 @@ from subprocess import Popen, PIPE from config import settings, arglistify +logger=logging.getLogger(__name__) + necessary_opts=['--log-json', '--progress'] necessary_opts_for={ @@ -39,7 +41,7 @@ def launch(self, passphrase=None): cmd=self.construct_cmdline() - logging.info('Launching ' + str(cmd)) + logger.info('Launching ' + str(cmd)) env=os.environ.copy() if passphrase: @@ -64,13 +66,13 @@ stream=self.proc.stdout line=stream.read(-1) if line==b'': - logging.debug('Borg stdout pipe EOF?') + logger.debug('Borg stdout pipe EOF?') return None try: return json.loads(line) except: - logging.warning('JSON parse failed on: "%s"' % line) + logger.warning('JSON parse failed on: "%s"' % line) return None def read_log(self): @@ -78,7 +80,7 @@ try: line=stream.readline() except err: - logging.debug('Pipe read failed: %s' % str(err)) + logger.debug('Pipe read failed: %s' % str(err)) return {'type': 'log_message', 'levelname': 'CRITICAL', @@ -88,7 +90,7 @@ if line==b'': - logging.debug('Borg stderr pipe EOF?') + logger.debug('Borg stderr pipe EOF?') return None @@ -98,7 +100,7 @@ res['type']='UNKNOWN' return res except: - logging.debug('JSON parse failed on: "%s"' % str(line)) + logger.debug('JSON parse failed on: "%s"' % str(line)) errmsg=line for line in iter(stream.readline, b''): diff -r 3dd525652dc8 -r b4b4bb7a2ec5 ui.py --- a/ui.py Sun Jan 21 12:10:57 2018 +0000 +++ b/ui.py Sun Jan 21 13:34:12 2018 +0000 @@ -10,6 +10,8 @@ from config import settings import objc +logger=logging.getLogger(__name__) + INACTIVE=0 ACTIVE=1 OFFLINE=2 @@ -146,14 +148,14 @@ def refresh_ui(self): with self.lock: self.refresh_timer=None - logging.debug('Rebuilding menu') + logger.debug('Rebuilding menu') menu, active=self.__rebuild_menu() self.menu.clear() self.menu.update(menu) self.title=traynames[active] def __status_callback(self, obj, index, status, errorlog): - logging.debug('Status callbackup %s' % str(status)) + logger.debug('Status callbackup %s' % str(status)) with self.lock: self.statuses[index]=status @@ -167,7 +169,7 @@ else: msgid=errorlog['msgid'] - logging.debug('Opening notification for error') + logger.debug('Opening notification for error') # Workaround to rumps brokenness # See https://github.com/jaredks/rumps/issues/59 @@ -181,7 +183,7 @@ def __menu_select_backup(self, sender, b): #sender.state=not sender.state - logging.debug("Manually backup '%s'", b.name) + logger.debug("Manually backup '%s'", b.name) b.create(None) @rumps.notifications