diff --git a/README.md b/README.md index bb3c1cd..b79ba86 100644 --- a/README.md +++ b/README.md @@ -56,6 +56,7 @@ General options: --dryrun Don't actually do anything --snapper-config Only operate on a single snapper config given by its name + -v increase verbosity, can be repeated twice Commands: init Initialize (create) the configured borg repositories diff --git a/snapborg/borg.py b/snapborg/borg.py index 1aaceca..32b2cac 100644 --- a/snapborg/borg.py +++ b/snapborg/borg.py @@ -1,9 +1,12 @@ +import json import os import subprocess import sys from subprocess import CalledProcessError -from .util import restrict_keys, selective_merge +from .util import restrict_keys, selective_merge, init_snapborg_logger + +LOG = init_snapborg_logger(__name__) DEFAULT_REPO_CONFIG = { "storage": { @@ -44,9 +47,17 @@ def init(self, dryrun=False): self.repopath, ] launch_borg(borg_init_invocation, self.passphrase, - print_output=self.is_interactive, dryrun=dryrun) - - def backup(self, backup_name, *paths, exclude_patterns=[], timestamp=None, dryrun=False): + log_output=self.is_interactive, dryrun=dryrun) + + def backup( + self, + backup_name, + *paths, + exclude_patterns=[], + timestamp=None, + snapborg_id=None, + dryrun=False, + ): borg_create = ["create", "--one-file-system", @@ -54,6 +65,8 @@ def backup(self, backup_name, *paths, exclude_patterns=[], timestamp=None, dryru "--exclude-caches", "--checkpoint-interval", "600", "--compression", self.compression] + if snapborg_id: + borg_create += ("--comment", f"snapborg_id={snapborg_id}") if timestamp: borg_create += ("--timestamp", timestamp.isoformat()) for e in exclude_patterns: @@ -68,14 +81,14 @@ def backup(self, backup_name, *paths, exclude_patterns=[], timestamp=None, dryru launch_borg( borg_invocation, self.passphrase, - print_output=self.is_interactive, + log_output=False, dryrun=dryrun ) def delete(self, backup_name, dryrun=False): borg_delete = ["delete", f"{self.repopath}::{backup_name}"] launch_borg(borg_delete, self.passphrase, - print_output=self.is_interactive, + log_output=self.is_interactive, dryrun=dryrun) def prune(self, override_retention_settings=None, dryrun=False): @@ -92,10 +105,29 @@ def prune(self, override_retention_settings=None, dryrun=False): launch_borg( borg_prune_invocation, self.passphrase, - print_output=self.is_interactive, + log_output=self.is_interactive, dryrun=dryrun ) + def list_backups(self): + borg_list = [ + "list", + "--format", + "{archive} {id} {name} {start} {time} {comment}", + "--json", + f"{self.repopath}", + ] + stdout = ( + launch_borg(borg_list, self.passphrase, log_output=False, dryrun=False) + or "{}" + ) + data = json.loads(stdout) + return data.get("archives", []) + + def list_backup_ids(self): + backup_list = self.list_backups() + return [backup.get("comment", "=").split("=")[1] for backup in backup_list] + def get_retention_config(self): return self.retention @@ -132,13 +164,13 @@ def get_password(password): with open(password) as pwfile: password = pwfile.read().strip() except FileNotFoundError: - print("tried to use password as file, but could not find it") + LOG.fatal("tried to use password as file, but could not find it") raise return password -def launch_borg(args, password=None, print_output=False, dryrun=False): +def launch_borg(args, password=None, log_output=False, dryrun=False): """ launch borg and supply the password by environment @@ -147,23 +179,29 @@ def launch_borg(args, password=None, print_output=False, dryrun=False): cmd = ["borg"] + args - if print_output: - print(f"$ {' '.join(cmd)}") + LOG.debug("$ {}".format(' '.join(cmd))) + buffer = "" if not dryrun: env = {'BORG_PASSPHRASE': password} if password else {} # TODO: parse output from JSON log lines - try: - if print_output: - subprocess.run(cmd, env=env, check=True) - else: - subprocess.check_output(cmd, - stderr=subprocess.STDOUT, - env=env) - except CalledProcessError as e: - if e.returncode == 1: + + # launch process + proc = subprocess.Popen( + cmd, env=env, stdout=subprocess.PIPE, stderr=subprocess.STDOUT + ) + # rather than wait for process to finish, print output in real time + while proc.poll() is None: + line = proc.stdout.readline().decode().rstrip("\n") + if len(line) != 0: + buffer += line + if log_output: + LOG.info(line) + if proc.returncode != 0: + if proc.returncode == 1: # warning(s) happened, don't raise - if not print_output: - print(f"Borg command execution gave warnings:\n{e.output.decode()}") + if log_output: + LOG.info(f"Borg command execution gave warnings:\n{buffer}") else: - raise + raise CalledProcessError(cmd=cmd, returncode=proc.returncode) + return buffer diff --git a/snapborg/commands/snapborg.py b/snapborg/commands/snapborg.py index 3871c64..bb61110 100755 --- a/snapborg/commands/snapborg.py +++ b/snapborg/commands/snapborg.py @@ -22,7 +22,9 @@ from ..borg import BorgRepo from ..retention import get_retained_snapshots from ..snapper import SnapperConfig -from ..util import selective_merge +from ..util import selective_merge, init_snapborg_logger, set_loglevel + +LOG = init_snapborg_logger(__name__) DEFAULT_CONFIG = { "configs": [] @@ -45,6 +47,7 @@ def main(): cli.add_argument("--dryrun", action="store_true", help="Don't actually execute commands") cli.add_argument("--snapper-config", default=None, dest="snapper_config", help="The name of a snapper config to operate on") + cli.add_argument("-v", action="count", default=0, help="increase verbosity, can be repeated twice") subp = cli.add_subparsers(dest="mode", required=True) subp.add_parser("prune", help="Prune the borg archives using the retention settings from the " @@ -64,6 +67,7 @@ def main(): "user data") args = cli.parse_args() + set_loglevel(args.v) with open(args.cfg, 'r') as stream: cfg = selective_merge(yaml.safe_load(stream), DEFAULT_CONFIG) @@ -92,12 +96,20 @@ def main(): def list_snapshots(cfg, configs): print("Listing snapper snapshots:") for config in configs: + borg_repo = BorgRepo.create_from_config(config) snapper_config = SnapperConfig.get(config["name"]) print(f"\tConfig {snapper_config.name} for subvol {snapper_config.get_path()}:") snapshots = snapper_config.get_snapshots() + repo_snapshot_ids = borg_repo.list_backup_ids() for s in snapshots: print( - f"\t\tSnapshot {s.get_number()} from {s.get_date()} is backed up: {s.is_backed_up()}") + "\t\tBorg repo {} has backup of snapshot {} from {}: {}".format( + config["name"], + s.get_number(), + s.get_date(), + s.get_snapborg_id() in repo_snapshot_ids, + ) + ) def get_configs(cfg, config_arg=None): @@ -142,14 +154,14 @@ def backup(cfg, snapper_configs, recreate, prune_old_backups, dryrun): status_map[config["name"]] = True except Exception as e: status_map[config["name"]] = e - print("\nBackup results:") + LOG.info("Backup results:") has_error = False for config_name, status in status_map.items(): if status is True: - print(f"OK {config_name}") + LOG.info(f"\t{config_name}:\tOK") else: has_error = True - print(f"FAILED {config_name}: {status}") + LOG.error(f"\t{config_name}: FAILED - {status}") if has_error: raise Exception("Snapborg failed!") @@ -161,7 +173,7 @@ def backup_config(config, recreate, dryrun): """ Backup a single snapper config """ - print(f"Backing up snapshots for snapper config '{config['name']}'...") + LOG.info(f"Backing up snapshots for snapper config '{config['name']}'...") snapper_config = None snapshots = None try: @@ -169,7 +181,7 @@ def backup_config(config, recreate, dryrun): # when we have the config, extract the snapshots which are not yet backed up snapshots = snapper_config.get_snapshots() if len(snapshots) == 0: - print("No snapshots from snapper found!") + LOG.warning("No snapshots from snapper found!") return except subprocess.SubprocessError: raise Exception(f"Failed to get snapper config {config['name']}!") @@ -177,11 +189,13 @@ def backup_config(config, recreate, dryrun): repo = BorgRepo.create_from_config(config) # now determine which snapshots need to be backed up retention_config = repo.get_retention_config() + backed_up_snapshot_ids = {b for b in repo.list_backup_ids()} candidates = [ snapshot for snapshot in get_retained_snapshots( - snapshots, lambda s: s.get_date(), - **retention_config) if(not snapshot.is_backed_up() or recreate) + snapshots, lambda s: s.get_date(), **retention_config + ) + if snapshot.get_snapborg_id() not in backed_up_snapshot_ids and not recreate ] with snapper_config.prevent_cleanup(snapshots=candidates, dryrun=dryrun): @@ -194,10 +208,11 @@ def backup_config(config, recreate, dryrun): if has_error and not config["fault_tolerant_mode"]: raise Exception(f"Error(s) while transferring backups for {snapper_config.name}!") + repo_snapshot_ids = repo.list_backup_ids() if config["last_backup_max_age"].total_seconds() > 0: # fail if the creation date of the newest snapshot successfully backed up is too old snapshots = snapper_config.get_snapshots() - backed_up = [ s for s in snapshots if s.is_backed_up() ] + backed_up = [ s for s in snapshots if s.get_snapborg_id() in repo_snapshot_ids ] if len(snapshots) > 0 and len(backed_up) == 0: raise Exception("No snapshots have been transferred to the borg repo!") newest_backed_up = max( @@ -211,7 +226,7 @@ def backup_config(config, recreate, dryrun): def backup_candidate(snapper_config, borg_repo, candidate, recreate, exclude_patterns, dryrun=False): - print(f"Backing up snapshot number {candidate.get_number()} " + LOG.info(f"Backing up snapshot number {candidate.get_number()} " f"from {candidate.get_date().isoformat()}...") path_to_backup = candidate.get_path() backup_name = f"{snapper_config.name}-{candidate.get_number()}-{candidate.get_date().isoformat()}" @@ -219,12 +234,18 @@ def backup_candidate(snapper_config, borg_repo, candidate, recreate, if recreate: borg_repo.delete(backup_name, dryrun=dryrun) candidate.purge_userdata(dryrun=dryrun) - borg_repo.backup(backup_name, path_to_backup, timestamp=candidate.get_date(), - exclude_patterns=exclude_patterns, dryrun=dryrun) - candidate.set_backed_up(dryrun=dryrun) + snapborg_id = candidate.generate_snapborg_id(dryrun=dryrun) + borg_repo.backup( + backup_name, + path_to_backup, + timestamp=candidate.get_date(), + exclude_patterns=exclude_patterns, + snapborg_id=snapborg_id, + dryrun=dryrun, + ) return True except subprocess.CalledProcessError as e: - print(f"Error backing up snapshot number {candidate.get_number()}!\n\t{e}") + LOG.error(f"Error backing up snapshot number {candidate.get_number()}!\n\t{e}") return False @@ -256,5 +277,5 @@ def clean_snapper(cfg, snapper_configs, dryrun): try: main() except Exception as e: - print(f"Snapborg failed: {e}!") + LOG.fatal(f"Snapborg failed: {e}!") sys.exit(1) diff --git a/snapborg/snapper.py b/snapborg/snapper.py index a6398e1..315ceab 100644 --- a/snapborg/snapper.py +++ b/snapborg/snapper.py @@ -2,9 +2,13 @@ import subprocess from datetime import datetime from contextlib import contextmanager +import uuid from packaging import version +from .util import init_snapborg_logger + +LOG = init_snapborg_logger(__name__) def check_snapper(): """ @@ -34,11 +38,11 @@ def run_snapper(args, config: str = None, dryrun=False): *args ] if dryrun: - print(args_new) - return None + LOG.info(args_new) + return {} else: output = subprocess.check_output(args_new).decode().strip() - return json.loads(output) if output != "" else None + return json.loads(output) if output != "" else {} class SnapperConfig: @@ -66,7 +70,7 @@ def get_snapshots(self): @classmethod def get(cls, config_name: str): return cls(config_name, run_snapper(["get-config"], config_name)) - + @contextmanager def prevent_cleanup(self, snapshots=None, dryrun=False): """ @@ -78,7 +82,7 @@ def prevent_cleanup(self, snapshots=None, dryrun=False): for s in snapshots: s.prevent_cleanup(dryrun=dryrun) - + try: yield self finally: @@ -90,10 +94,6 @@ class SnapperSnapshot: def __init__(self, config: SnapperConfig, info): self.config = config self.info = info - if (info["userdata"] or dict()).get("snapborg_backup") == "true": - self._is_backed_up = True - else: - self._is_backed_up = False self._cleanup = info["cleanup"] def get_date(self): @@ -102,27 +102,42 @@ def get_date(self): def get_path(self): return f"{self.config.get_path()}/.snapshots/{self.get_number()}/snapshot" - def is_backed_up(self): - return self._is_backed_up - def get_number(self): return self.info["number"] + def get_snapborg_id(self): + return (self.info["userdata"] or dict()).get("snapborg_id") + + def generate_snapborg_id(self, dryrun=False): + snapshot_uuid = self.get_snapborg_id() + if snapshot_uuid is None: + if self.info["userdata"] is None: + self.info["userdata"] = {} + snapshot_uuid = uuid.uuid4() + self.info["userdata"]["snapborg_id"] = snapshot_uuid + run_snapper( + [ + "modify", + "--userdata", + f"snapborg_id={snapshot_uuid}", + f"{self.get_number()}", + ], + self.config.name, + dryrun=dryrun, + ) + return self.info["userdata"]["snapborg_id"] + def purge_userdata(self, dryrun=False): run_snapper( - ["modify", "--userdata", "snapborg_backup=", f"{self.get_number()}"], - self.config.name, dryrun=dryrun) - - def set_backed_up(self, dryrun=False): - run_snapper(["modify", "--userdata", "snapborg_backup=true", - f"{self.get_number()}"], self.config.name, dryrun=dryrun) - self._is_backed_up = True + ["modify", "--userdata", "snapborg_id=", f"{self.get_number()}"], + self.config.name, + dryrun=dryrun, + ) def prevent_cleanup(self, dryrun=False): """ Prevents this snapshot from being cleaned up """ - run_snapper( ["modify", "--cleanup-algorithm", "", f"{self.get_number()}"], self.config.name, dryrun=dryrun diff --git a/snapborg/util.py b/snapborg/util.py index 2a1464e..182c0b1 100644 --- a/snapborg/util.py +++ b/snapborg/util.py @@ -1,3 +1,8 @@ +import logging +import os +import sys + + def selective_merge(base_obj, delta_obj, restrict_keys=False): """ Recursively merge dict delta_obj into base_obj by adding all key/value @@ -60,4 +65,31 @@ def split(data, pred): yes.append(d) else: no.append(d) - return (yes, no) \ No newline at end of file + return (yes, no) + + +def set_loglevel(verbosity_level): + loglevel = logging.WARNING + if verbosity_level > 0: + loglevel = logging.INFO + if verbosity_level > 1: + loglevel = logging.DEBUG + + for logger_name in logging.root.manager.loggerDict: + logging.getLogger(logger_name).setLevel(loglevel) + return loglevel + + +def init_snapborg_logger(logger_name): + is_interactive = os.isatty(sys.stdout.fileno()) + logger = logging.getLogger(logger_name) + logger.setLevel(logging.INFO) + if is_interactive: + formatter = logging.Formatter("%(asctime)s - %(levelname)s - %(message)s") + else: + # if running in non-interactive mode, typically through systemd + formatter = logging.Formatter("%(levelname)s - %(name)s:%(lineno)d - %(message)s") + ch = logging.StreamHandler() + ch.setFormatter(formatter) + logger.addHandler(ch) + return logger