fix backups

3 files changed, 107 insertions, 75 deletions

diff --git a/modules/zfssnap/default.nix b/modules/zfssnap/default.nix
index 42cdf46f..735e73ec 100644
--- a/modules/zfssnap/default.nix
+++ b/modules/zfssnap/default.nix
@@ -1,32 +1,20 @@
-{ config, pkgs, lib, ... }:
+{ config, pkgs, lib, flakeInputs, ... }:
 
 with lib;
 
 let
-  zfssnap = pkgs.stdenv.mkDerivation rec {
-    name = "zfssnap";
-    src = ./zfssnap.py;
+  zfssnap = flakeInputs.mach-nix.lib.${config.nixpkgs.system}.buildPythonPackage rec {
+    pname = "zfssnap";
+    src = ./zfssnap;
+    version = "0.0.0";
+    ignoreDataOutdated = true;
 
-    phases = [ "buildPhase" "checkPhase" "installPhase" ];
-
-    buildInputs = with pkgs; [makeWrapper];
-
-    python = pkgs.python39.withPackages (ps: with ps; [pyxdg pytimeparse python-dateutil]);
-
-    buildPhase = ''
-      substitute $src zfssnap \
-        --subst-var-by python ${escapeShellArg python}
-    '';
-
-    doCheck = true;
-    checkPhase = ''
-      ${python}/bin/python -m py_compile zfssnap
+    requirements = ''
+      pyxdg
+      pytimeparse
+      python-dateutil
     '';
-
-    installPhase = ''
-      install -m 0755 -D -t $out/bin \
-        zfssnap
-
+    postInstall = ''
       wrapProgram $out/bin/zfssnap \
         --prefix PATH : ${makeBinPath [config.boot.zfs.package]}
     '';
@@ -71,7 +59,9 @@ in {
       before = [ "zfssnap-prune.service" ];
       serviceConfig = {
         Type = "oneshot";
-        ExecStart = "${zfssnap}/bin/zfssnap -v";
+        ExecStart = "${zfssnap}/bin/zfssnap -vv";
+
+        LogRateLimitIntervalSec = 0;
       };
     };
     systemd.services."zfssnap-prune" = {
@@ -82,7 +72,9 @@ in {
         ExecStart = let
           mkSectionName = name: strings.escape [ "[" "]" ] (strings.toUpper name);
           zfssnapConfig = generators.toINI { inherit mkSectionName; } cfg.config;
-        in "${zfssnap}/bin/zfssnap -vv prune --config=${pkgs.writeText "zfssnap.ini" zfssnapConfig}";
+        in "${zfssnap}/bin/zfssnap -vv prune --exec-newest --config=${pkgs.writeText "zfssnap.ini" zfssnapConfig}"; # DEBUG
+
+        LogRateLimitIntervalSec = 0;
       };
     };
 
diff --git a/modules/zfssnap/zfssnap/setup.py b/modules/zfssnap/zfssnap/setup.py
new file mode 100644
index 00000000..6c58757d
--- /dev/null
+++ b/modules/zfssnap/zfssnap/setup.py
@@ -0,0 +1,10 @@
+from setuptools import setup
+
+setup(name='zfssnap',
+      packages=['zfssnap'],
+      entry_points={
+          'console_scripts': [
+              'zfssnap=zfssnap.__main__:main',
+          ],
+      }
+)
diff --git a/modules/zfssnap/zfssnap.py b/modules/zfssnap/zfssnap/zfssnap/__main__.py
index a8dae75f..a0eade78 100644
--- a/modules/zfssnap/zfssnap.py
+++ b/modules/zfssnap/zfssnap/zfssnap/__main__.py
@@ -45,6 +45,9 @@ TIME_PATTERNS = OrderedDict([
     ("yearly", lambda t: t.strftime('%Y')),
 ])
 
+PROP_DO_AUTO_SNAPSHOT = 'li.yggdrasil:auto-snapshot'
+PROP_IS_AUTO_SNAPSHOT = 'li.yggdrasil:is-auto-snapshot'
+
 @dataclass(eq=True, order=True, frozen=True)
 class Snap:
     name: str
@@ -68,25 +71,28 @@ def _snap_name(item, time=_now()):
 
 def _log_cmd(*args):
     fmt_args = ' '.join(map(shlex.quote, args))
-    logger.debug(f'Running command: {fmt_args}')
+    logger.debug('Running command: %s', fmt_args)
 
 def _get_items():
     items = {}
 
-    args = ['zfs', 'get', '-H', '-p', '-o', 'name,value', '-t', 'filesystem,volume', '-s', 'local,default,inherited,temporary,received', 'li.yggdrasil:auto-snapshot']
+    args = ['zfs', 'get', '-H', '-p', '-o', 'name,value', '-t', 'filesystem,volume', PROP_DO_AUTO_SNAPSHOT]
     _log_cmd(*args)
     with subprocess.Popen(args, stdout=subprocess.PIPE) as proc:
         text_stdout = io.TextIOWrapper(proc.stdout)
-        reader = csv.DictReader(text_stdout, fieldnames=['name', 'setting'], delimiter='\t', quoting=csv.QUOTE_NONE)
+        reader = csv.DictReader(text_stdout, fieldnames=['name', 'value'], delimiter='\t', quoting=csv.QUOTE_NONE)
         Row = namedtuple('Row', reader.fieldnames)
         for row in [Row(**data) for data in reader]:
-            items[row.name] = bool(strtobool(row.setting))
+            if not row.value or row.value == '-':
+                continue
+
+            items[row.name] = bool(strtobool(row.value))
 
     return items
 
 def _get_snaps(only_auto=True):
     snapshots = defaultdict(list)
-    args = ['zfs', 'list', '-H', '-p', '-t', 'snapshot', '-o', 'name,li.yggdrasil:is-auto-snapshot,creation']
+    args = ['zfs', 'list', '-H', '-p', '-t', 'snapshot', '-o', f'name,{PROP_IS_AUTO_SNAPSHOT},creation']
     _log_cmd(*args)
     with subprocess.Popen(args, stdout=subprocess.PIPE) as proc:
         text_stdout = io.TextIOWrapper(proc.stdout)
@@ -102,17 +108,26 @@ def _get_snaps(only_auto=True):
 
     return snapshots
 
-def prune(config, dry_run, keep_newest, do_exec):
+def prune(config, dry_run, keep_newest, do_exec, exec_newest):
     do_exec = do_exec and 'EXEC' in config
     prune_timezone = config.gettimezone('KEEP', 'timezone', fallback=tzutc())
-    logger.debug(f'prune timezone: {prune_timezone}')
+    logger.debug('prune timezone: %s', prune_timezone)
 
     items = _get_snaps()
 
+    kept_count = defaultdict(lambda: defaultdict(lambda: 0))
+    kept_because = OrderedDict()
+    def keep_because(base, snap, rule, period=None):
+        nonlocal kept_count, kept_because
+        kept_count[rule][base] += 1
+        if snap not in kept_because:
+            kept_because[snap] = deque()
+        kept_because[snap].append(KeptBecause(rule=rule, ix=kept_count[rule][base], base=base, period=period))
+
     exec_candidates = set()
     if do_exec:
         exec_timezone = config.gettimezone('EXEC', 'timezone', fallback=prune_timezone)
-        logger.debug(f'exec timezone: {exec_timezone}')
+        logger.debug('exec timezone: %s', exec_timezone)
 
         for rule, pattern in TIME_PATTERNS.items():
             desired_count = config.getint('EXEC', rule, fallback=0)
@@ -120,7 +135,7 @@ def prune(config, dry_run, keep_newest, do_exec):
             for base, snaps in items.items():
                 periods = OrderedDict()
 
-                for snap in sorted(snaps, key=lambda snap: snap.creation):
+                for snap in sorted(snaps, key=lambda snap: snap.creation, reverse=exec_newest):
                     period = pattern(snap.creation.astimezone(exec_timezone))
                     if period not in periods:
                         periods[period] = deque()
@@ -134,15 +149,16 @@ def prune(config, dry_run, keep_newest, do_exec):
 
                     for snap in period_snaps:
                         exec_candidates.add(snap)
-                        logger.debug(f'{snap.name} is exec candidate')
+                        logger.debug('‘%s’ is exec candidate', snap.name)
                         to_exec -= 1
                         break
 
                 if to_exec > 0:
-                    logger.debug(f'Missing {to_exec} to fulfill exec {rule}={desired_count} for ‘{base}’')
+                    logger.debug('Missing %d  to fulfill exec %s=%d for ‘%s’', to_exec, rule, desired_count, base)
 
         check_cmd = config.get('EXEC', 'check', fallback=None)
         if check_cmd:
+            logger.debug('exec_candidates=%s', exec_candidates)
             already_execed = set()
             for snap in exec_candidates:
                 args = []
@@ -152,7 +168,20 @@ def prune(config, dry_run, keep_newest, do_exec):
                 check_res = subprocess.run(args)
                 if check_res.returncode == 0:
                     already_execed.add(snap)
-                    logger.debug(f'{snap.name} already execed')
+                    logger.debug('‘%s’ already execed', snap.name)
+                elif check_res.returncode == 124:
+                    already_execed.add(snap)
+                    logger.warn('‘%s’ ignored', snap.name)
+                    pass
+                elif check_res.returncode == 125:
+                    already_execed.add(snap)
+                    logger.info('‘%s’ ignored but specified for keeping, doing so...', snap.name)
+                    base_name, _, _ = snap.name.rpartition('@')
+                    keep_because(base_name, snap.name, 'exec-ignored')
+                elif check_res.returncode == 126:
+                    logger.debug('‘%s’ to exec', snap.name)
+                else:
+                    check_res.check_returncode()
             exec_candidates -= already_execed
 
         exec_cmd = config.get('EXEC', 'cmd', fallback=None)
@@ -160,28 +189,26 @@ def prune(config, dry_run, keep_newest, do_exec):
         if exec_cmd:
             execed = set()
             for snap in sorted(exec_candidates, key=lambda snap: snap.creation):
-                if len(execed) >= exec_count:
-                    logger.debug(f'exc_count of {exec_count} reached')
+                if exec_count > 0 and len(execed) >= exec_count:
+                    logger.debug('exec_count of %d reached', exec_count)
                     break
 
                 args = []
                 args += shlex.split(exec_cmd)
                 args += [snap.name]
                 _log_cmd(*args)
-                subprocess.run(args).check_returncode()
+                p = subprocess.run(args)
+                if p.returncode == 125:
+                    logger.warn('got dry-run returncode for ‘%s’, keeping...', snap.name)
+                    base_name, _, _ = snap.name.rpartition('@')
+                    keep_because(base_name, snap.name, 'exec-dryrun')
+                    pass
+                else:
+                    p.check_returncode()
                 execed.add(snap)
 
             exec_candidates -= execed
 
-    kept_count = defaultdict(lambda: defaultdict(lambda: 0))
-    kept_because = OrderedDict()
-    def keep_because(base, snap, rule, period=None):
-        nonlocal kept_count, kept_because
-        kept_count[rule][base] += 1
-        if snap not in kept_because:
-            kept_because[snap] = deque()
-        kept_because[snap].append(KeptBecause(rule=rule, ix=kept_count[rule][base], base=base, period=period))
-
     for candidate in exec_candidates:
         base_name, _, _ = candidate.name.rpartition('@')
         keep_because(base_name, candidate.name, 'exec-candidate')
@@ -191,10 +218,10 @@ def prune(config, dry_run, keep_newest, do_exec):
         for base, snaps in items.items():
             time_ref = max(snaps, key=lambda snap: snap.creation, default=None)
             if not time_ref:
-                logger.warn(f'Nothing to keep for ‘{base}’')
+                logger.warn('Nothing to keep for ‘%s’', base)
                 continue
 
-            logger.info(f'Using ‘{time_ref.name}’ as time reference for ‘{base}’')
+            logger.info('Using ‘%s’ as time reference for ‘%s’', time_ref.name, base)
             within_cutoff = time_ref.creation - within
 
             for snap in snaps:
@@ -227,11 +254,10 @@ def prune(config, dry_run, keep_newest, do_exec):
                     break
 
             if to_keep > 0:
-                logger.debug(f'Missing {to_keep} to fulfill prune {rule}={desired_count} for ‘{base}’')
+                logger.debug('Missing %d to fulfill prune %s=%d for ‘%s’', to_keep, rule, desired_count, base)
 
     for snap, reasons in kept_because.items():
-        reasons_str = ', '.join(map(str, reasons))
-        logger.info(f'Keeping ‘{snap}’ because: {reasons_str}')
+        logger.info('Keeping ‘%s’ because: %s', snap, ', '.join(map(str, reasons)))
     all_snaps = {snap.name for _, snaps in items.items() for snap in snaps}
     to_destroy = all_snaps - {*kept_because}
     if not to_destroy:
@@ -245,9 +271,9 @@ def prune(config, dry_run, keep_newest, do_exec):
         _log_cmd(*args)
         subprocess.run(args, check=True)
         if dry_run:
-            logger.info(f'Would have pruned ‘{snap}’')
+            logger.info('Would have pruned ‘%s’', snap)
         else:
-            logger.info(f'Pruned ‘{snap}’')
+            logger.info('Pruned ‘%s’', snap)
 
 def rename(snapshots, destroy=False, set_is_auto=False):
     args = ['zfs', 'get', '-H', '-p', '-o', 'name,value', 'creation', *snapshots]
@@ -262,29 +288,29 @@ def rename(snapshots, destroy=False, set_is_auto=False):
             base_name, _, _ = row.name.rpartition('@')
             new_name = _snap_name(base_name, time=creation)
             if new_name == row.name:
-                logger.debug(f'Not renaming ‘{row.name}’ since name is already correct')
+                logger.debug('Not renaming ‘%s’ since name is already correct', row.name)
                 continue
 
             if new_name in renamed_to:
                 if destroy:
-                    logger.warning(f'Destroying ‘{row.name}’ since ‘{new_name}’ was already renamed to')
+                    logger.warning('Destroying ‘%s’ since ‘%s’ was already renamed to', row.name, new_name)
                     args = ['zfs', 'destroy', row.name]
                     _log_cmd(*args)
                     subprocess.run(args, check=True)
                 else:
-                    logger.info(f'Skipping ‘{row.name}’ since ‘{new_name}’ was already renamed to')
+                    logger.info('Skipping ‘%s’ since ‘%s’ was already renamed to', row.name, new_name)
 
                 continue
 
-            logger.info(f'Renaming ‘{row.name}’ to ‘{new_name}’')
+            logger.info('Renaming ‘%s’ to ‘%s’', row.name, new_name)
             args = ['zfs', 'rename', row.name, new_name]
             _log_cmd(*args)
             subprocess.run(args, check=True)
             renamed_to.add(new_name)
 
             if set_is_auto:
-                logger.info(f'Setting is-auto-snapshot on ‘{new_name}’')
-                args = ['zfs', 'set', 'li.yggdrasil:is-auto-snapshot=true', new_name]
+                logger.info('Setting is-auto-snapshot on ‘%s’', new_name)
+                args = ['zfs', 'set', f'{PROP_IS_AUTO_SNAPSHOT}=true', new_name]
                 _log_cmd(*args)
                 subprocess.run(args, check=True)
 
@@ -301,7 +327,7 @@ def autosnap():
         else:
             all_snap_names |= snap_names
 
-        args = ['zfs', 'snapshot', '-o', 'li.yggdrasil:is-auto-snapshot=true']
+        args = ['zfs', 'snapshot', '-o', f'{PROP_IS_AUTO_SNAPSHOT}=true']
         if recursive:
             args += ['-r']
         args += snap_names
@@ -324,7 +350,7 @@ def autosnap():
             await asyncio.gather(*tasks)
         asyncio.run(run_tasks())
     for snap in all_snap_names:
-        logger.info(f'Created ‘{snap}’')
+        logger.info('Created ‘%s’', snap)
     if all_snap_names:
         rename(snapshots=all_snap_names)
 
@@ -347,7 +373,8 @@ def main():
     sys.excepthook = log_exceptions
 
     parser = argparse.ArgumentParser(prog='zfssnap')
-    parser.add_argument('--verbose', '-v', action='count', default=0)
+    parser.add_argument('--verbose', '-v', dest='log_level', action='append_const', const=-1)
+    parser.add_argument('--quiet', '-q', dest='log_level', action='append_const', const=1)
     subparsers = parser.add_subparsers()
     parser.set_defaults(cmd=autosnap)
     rename_parser = subparsers.add_parser('rename')
@@ -359,26 +386,29 @@ def main():
     prune_parser.add_argument('--config', '-c', dest='config_files', nargs='*', default=list())
     prune_parser.add_argument('--dry-run', '-n', action='store_true', default=False)
     prune_parser.add_argument('--keep-newest', action='store_true', default=False)
+    prune_parser.add_argument('--exec-newest', action='store_true', default=False)
     prune_parser.add_argument('--no-exec', dest='do_exec', action='store_false', default=True)
     prune_parser.set_defaults(cmd=prune)
     args = parser.parse_args()
 
-    if args.verbose <= 0:
-        logger.setLevel(logging.WARNING)
-    elif args.verbose <= 1:
-        logger.setLevel(logging.INFO)
-    else:
-        logger.setLevel(logging.DEBUG)
+
+    LOG_LEVELS = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL]
+    DEFAULT_LOG_LEVEL = logging.ERROR
+    log_level = LOG_LEVELS.index(DEFAULT_LOG_LEVEL)
+
+    for adjustment in args.log_level or ():
+        log_level = min(len(LOG_LEVELS) - 1, max(log_level + adjustment, 0))
+    logger.setLevel(LOG_LEVELS[log_level])
 
     cmdArgs = {}
-    for copy in {'snapshots', 'dry_run', 'destroy', 'keep_newest', 'set_is_auto', 'do_exec'}:
+    for copy in {'snapshots', 'dry_run', 'destroy', 'keep_newest', 'exec_newest', 'set_is_auto', 'do_exec'}:
         if copy in vars(args):
             cmdArgs[copy] = vars(args)[copy]
     if 'config_files' in vars(args):
         def convert_timedelta(secs_str):
             secs=pytimeparse.parse(secs_str)
             if secs is None:
-                raise ValueError(f'Could not parse timedelta expression ‘{secs_str}’')
+                raise ValueError('Could not parse timedelta expression ‘%s’', secs_str)
             return timedelta(seconds=secs)
         config = configparser.ConfigParser(converters={
             'timedelta': convert_timedelta,
@@ -393,9 +423,9 @@ def main():
             return ', '.join(map(lambda file: f'‘{file}’', files))
 
         if not read_files:
-            raise Exception(f'Found no config files. Tried: {format_config_files(search_files)}')
+            raise Exception('Found no config files. Tried: %s', format_config_files(search_files))
 
-        logger.debug(f'Read following config files: {format_config_files(read_files)}')
+        logger.debug('Read following config files: %s', format_config_files(read_files))
 
         cmdArgs['config'] = config