changeset
On startup, for better scheduling, obtain previous backup time with 'borg list'
Sun, 28 Jan 2018 17:34:06 +0000
- author
- Tuomo Valkonen <tuomov@iki.fi>
- date
- Sun, 28 Jan 2018 17:34:06 +0000
- changeset 85
- 56a000d15965
- parent 84
- b613265bd679
- child 86
- 2fe66644c50d
On startup, for better scheduling, obtain previous backup time with 'borg list'
| borgend.py | file | annotate | diff | comparison | revisions | |
| borgend/backup.py | file | annotate | diff | comparison | revisions | |
| borgend/ui.py | file | annotate | diff | comparison | revisions |
--- a/borgend.py Sun Jan 28 14:56:13 2018 +0000 +++ b/borgend.py Sun Jan 28 17:34:06 2018 +0000 @@ -73,15 +73,9 @@ b=Backup(i, backupconfigs[i], scheduler) backups.append(b) - for r in repos: - r.start() - - for b in backups: - b.start() - if args.notray or platform.system()!='Darwin': # Wait for scheduler to finish - scheduler.join() + run=scheduler.join else: # This is needed for Ctrl+C to work. # TODO: proper exit handler, which seems to require @@ -91,7 +85,15 @@ # Start UI, and let it handle exit control from borgend.ui import BorgendTray tray=BorgendTray(backups); - tray.run() + run=tray.run + + for r in repos: + r.start() + + for b in backups: + b.start() + + run() except Exception as err: # TODO: Should write errors here to stderr;
--- a/borgend/backup.py Sun Jan 28 14:56:13 2018 +0000 +++ b/borgend/backup.py Sun Jan 28 17:34:06 2018 +0000 @@ -4,6 +4,7 @@ import logging import time +import datetime from enum import IntEnum from threading import Thread, Lock, Condition @@ -14,7 +15,7 @@ from .instance import BorgInstance from .scheduler import TerminableThread -logger=loggers.get(__name__) +_logger=loggers.get(__name__) JOIN_TIMEOUT=60 @@ -55,6 +56,9 @@ class Operation: CREATE='create' PRUNE='prune' + INFO='info' + LIST='list' + def __init__(self, operation, time, **kwargs): self.operation=operation self.time=time @@ -100,6 +104,39 @@ return tmp return None +def parse_borg_date(d, logger): + try: + res=datetime.datetime.strptime(d, '%Y-%m-%dT%H:%M:%S.%f') + except Exception: + logger.exception('Unable parse date from borg: "%s"' % d) + res=None + return res + +_checkpoint_str='.checkpoint' +_checkpoint_str_len=len(_checkpoint_str) + +def is_checkpoint(name): + i=name.rfind(_checkpoint_str); + return i>=0 and i+_checkpoint_str_len==len(name) + +def get_archive_time(a, logger): + if not 'name' in a: + logger.error('Borg archive list entry missing name') + return None, False + if is_checkpoint(a['name']): + logger.debug('Skipping checkpoint in archive list') + return None, True + + thistime=None + if 'start' in a: + thistime=parse_borg_date(a['start'], logger) + if not thistime and 'time' in a: + thistime=parse_borg_date(a['time'], logger) + if not thistime: + return None, False + + return thistime, True + # # The Backup class # @@ -111,9 +148,9 @@ self.backup_name=config.check_string(cfg, 'name', 'Name', loc0) - logger.debug("Configuring backup '%s'" % self.backup_name) + _logger.debug("Configuring backup '%s'" % self.backup_name) - self.logger=logger.getChild(self.backup_name) + self.logger=_logger.getChild(self.backup_name) loc="Backup '%s'" % self.backup_name @@ -169,8 +206,9 @@ self.current_operation=None self.scheduled_operation=None - self.lastrun_when=None - self.lastrun_finished=None + self.last_operation_finished=None + self.last_create_when=None + self.last_create_finished=None self.state=State.INACTIVE self.errors=Errors.OK self.timeclass=dreamtime.DreamTime @@ -210,10 +248,12 @@ if t=='progress_percent': current=safe_get_int(msg, 'current') total=safe_get_int(msg, 'total') + operation_no=safe_get_int(msg, 'operation') if current is not None and total is not None: with self._cond: self.current_operation.detail['progress_current']=current self.current_operation.detail['progress_total']=total + self.current_operation.detail['operation_no']=operation_no status, callback=self.__status_unlocked() elif t=='archive_progress': @@ -272,11 +312,45 @@ self.logger.debug('Borg result: %s' % str(res)) - with self._cond: - if res is None and self.errors.ok(): - self.logger.error('No result from borg despite no error in log') - self.errors=Errors.ERRORS + if res is None: + with self._cond: + if self.errors.ok(): + self.logger.error('No result from borg despite no error in log') + self.errors=Errors.ERRORS + elif self.current_operation.operation==Operation.CREATE: + with self._cond: + self.last_create_finished=time.monotonic() + self.last_create_when=self.current_operation.time.monotonic() + elif self.current_operation.operation==Operation.LIST: + ok=True + latest=None + if 'archives' in res and isinstance(res['archives'], list): + archives=res['archives'] + for a in archives: + if not isinstance(a, dict): + self.logger.error('Borg archive list entry not a dictionary') + ok=False + else: + thistime, this_ok=get_archive_time(a, self.logger) + if thistime and (not latest or thistime>latest): + latest=thistime + ok=ok and this_ok + else: + logger.error('Borg archive list missing "archives" entry') + if not ok: + with self._cond: + self.errors=self.errors.combine(Errors.ERRORS) + + if latest: + self.logger.info('borg info: Previous backup was on %s' % latest.isoformat()) + realtime=time.mktime(latest.timetuple()) + monotonic=realtime+time.monotonic()-time.time() + with self._cond: + self.last_create_finished=monotonic + self.last_create_when=monotonic + else: + self.logger.info('borg info: Could not discover a previous backup') def __do_launch(self, op, archive_or_repository, common_params, op_params, paths=[]): @@ -329,6 +403,9 @@ self.__do_launch(op, self.repository.location, params.common, [{'prefix': self.archive_prefix}] + params.create) + elif op.operation==Operation.LIST: + self.__do_launch(op, self.repository.location, params.common, + [{'prefix': self.archive_prefix}]) else: raise NotImplementedError("Invalid operation '%s'" % str(op.operation)) @@ -369,9 +446,8 @@ self.logger.error('Borg subprocess did not terminate') self.errors=self.errors.combine(Errors.ERRORS) - if self.current_operation.operation=='create': - self.lastrun_when=self.current_operation.time.monotonic() - self.lastrun_finished=time.monotonic() + now=time.monotonic() + self.last_operation_finished=now self.thread_res=None self.thread_log=None self.borg_instance=None @@ -459,28 +535,41 @@ self.__update_status() def __next_operation_unlocked(self): - # TODO: pruning as well - if not self.lastrun_finished: - initial_interval=self.retry_interval - if initial_interval==0: - initial_interval=self.backup_interval - if initial_interval==0: + if self.backup_interval==0: + # Manual backup + return None + elif not self.last_create_finished: + # Don't know when last create finished: try to get it from + # archive list. + if not self.errors.ok() and self.retry_interval==0: + # Do not retry in case of errors if retry interval is zero return None + elif self.last_operation_finished: + # Attempt ater retry interval if some operation has been run + # already + tm=dreamtime.MonotonicTime(self.last_operation_finished+self.retry_interval) else: - tm=self.timeclass.after(initial_interval) - return Operation(Operation.CREATE, tm, reason='initial') - elif not self.errors.ok(): + # Nothing has been attempted: run immediately + tm=dreamtime.MonotonicTime.now() + return Operation(Operation.LIST, tm, reason='initial') + elif not self.errors.ok() or not self.last_create_finished: + # Retry create in case of errors + + if not self.errors.ok(): + reason='retry' + else: + reason='initial' + if self.retry_interval==0: return None else: - tm=dreamtime.MonotonicTime(self.lastrun_finished+self.retry_interval) - return Operation(Operation.CREATE, tm, reason='retry') + basetime = self.last_create_finished or time.monotonic() + tm=dreamtime.MonotonicTime(basetime+self.retry_interval) + return Operation(Operation.CREATE, tm, reason=reason) else: - if self.backup_interval==0: - return None - else: - tm=self.timeclass.from_monotonic(self.lastrun_when+self.backup_interval) - return Operation(Operation.CREATE, tm) + # All ok - run create at standard backup interval + tm=self.timeclass.from_monotonic(self.last_create_when+self.backup_interval) + return Operation(Operation.CREATE, tm) def __status_unlocked(self): callback=self.__status_update_callback
--- a/borgend/ui.py Sun Jan 28 14:56:13 2018 +0000 +++ b/borgend/ui.py Sun Jan 28 17:34:06 2018 +0000 @@ -134,7 +134,10 @@ progress='' d=status.detail if 'progress_current' in d and 'progress_total' in d: - progress=' %d%%' % (d['progress_current']/d['progress_total']) + percentage = 100*float(d['progress_current'])/float(d['progress_total']) + progress=': %d%%' % int(round(percentage)) + if 'operation_no' in d: + progress='/#%d%s' % (d['operation_no'], progress) elif 'original_size' in d and 'deduplicated_size' in d: progress=' %s→%s' % (humanbytes(d['original_size']), humanbytes(d['deduplicated_size']))
