feat: update logging and output functionality

DEVELOPMENT.md

@@ -0,0 +1,8 @@
+# Logging and output
+
+We use the logging facility for both debugging and output to the user. If you
+want to output a normal message (replacement of `print()`) use `lg.warn()`. The
+name might feel counter-intuitive, but I don't want to hack the logging-system
+and add new levels. `INFO` is basically reseved for successful commands.
+Unsuccessful commands are logged on `ERROR`. You can also hide unsuccessful command
+using `hide_error=True` in `run_command`.

README.md

@@ -1,9 +1,45 @@
 # Pyaptly
 
-Automates the creation and managment of aptly mirrors and snapshots based on yml
+Automates the creation and managment of aptly mirrors and snapshots based on toml
 input files.
 
 **Important**: Corrently under heavy development:
 
 - For for the old version [switch to the master branch](https://github.com/adfinis/pyaptly/tree/master)
 - Main branch builds contain [alpha packages](https://github.com/adfinis/pyaptly/actions/runs/8147002919), see Artifacts
+
+# Debugging
+
+The most interesting mode for users is not `--debug` but `--info` which show all commands executed.
+
+```bash
+# pyaptly legacy -- --info --config pyaptly/tests/repo.toml repo create
+Command call
+  cmd:         gpg --no-default-keyring --keyring trustedkeys.gpg --list-keys --with-colons -> 0
+  stdout:     'tru::1:1709575833:0:3:1:5
+               pub:-:255:22:2841988729C7F3FF:1701882080:::-:::scESC:::::ed25519:::0:
+               fpr:::::::::6380C07FF6496016E01CF4522841988729C7F3FF:
+               uid:-::::1701882080::5BBE9C7E7AA5EEE3538F66274125D69FA727FD1E::Pyaptly Test 01 <[email protected]>::::::::::0:
+               sub:-:255:18:0A1CBEF26FE4F36E:1701882080::::::e:::::cv25519::
+               fpr:::::::::9EE64E40A5E3530D3E18A97C0A1CBEF26FE4F36E:
+               pub:-:255:22:EC54D33E5B5EBE98:1701882297:::-:::scESC:::::ed25519:::0:
+               fpr:::::::::660D45228AB6B59CCE48AFB3EC54D33E5B5EBE98:
+               uid:-::::1701882297::F3EF71B78669C0FC259A4078151BDC5815A6015D::Pyaptly Test 02 <[email protected]>::::::::::0:
+               sub:-:255:18:042FE0F5BB743B60:1701882297::::::e:::::cv25519::
+               fpr:::::::::AE58B62134E02AF8E5D55FF4042FE0F5BB743B60:'
+Command call
+  cmd:         aptly repo list -raw -> 0
+  stderr:     'Config file not found, creating default config at /root/.aptly.conf'
+Command call
+  cmd:         aptly mirror list -raw -> 0
+Command call
+  cmd:         aptly snapshot list -raw -> 0
+Command call
+  cmd:         aptly publish list -raw -> 0
+Command call
+  cmd:         aptly repo -architectures=amd64,i386 -distribution=stable -component=main create centrify -> 0
+  stdout:     'Local repo [centrify] successfully added.
+               You can run 'aptly repo add centrify ...' to add packages to repository.'
+```
+
+Commands that fail are always displayed in red on a tty, but actually only happen if something is broken.

pyaptly/command.py

@@ -291,7 +291,7 @@ def order_commands(commands, has_dependency_cb=lambda x: False):
         incoming_set = set([cmd for cmd in commands])
         assert incoming_set == scheduled_set
 
-        lg.info("Reordered commands: %s", [str(cmd) for cmd in scheduled])
+        lg.debug("Reordered commands: %s", [str(cmd) for cmd in scheduled])
 
         return scheduled
 

pyaptly/custom_logger.py

@@ -0,0 +1,37 @@
+import logging
+
+from colorama import Fore, Style
+
+from . import util
+
+
+class CustomFormatter(logging.Formatter):
+    debug = "%(levelname)s - %(filename)s:%(lineno)d: %(message)s"
+    info_warn = "%(message)s"
+    error_plus = "%(levelname)s: %(message)s"
+
+    FORMATS_COLOR = {
+        logging.DEBUG: Style.DIM + debug + Style.RESET_ALL,
+        logging.INFO: Fore.YELLOW + info_warn + Style.RESET_ALL,
+        logging.WARNING: info_warn,
+        logging.ERROR: Fore.RED + error_plus + Style.RESET_ALL,
+        logging.CRITICAL: Fore.MAGENTA + error_plus + Style.RESET_ALL,
+    }
+
+    FORMATS = {
+        logging.DEBUG: debug,
+        logging.INFO: info_warn,
+        logging.WARNING: info_warn,
+        logging.ERROR: error_plus,
+        logging.CRITICAL: error_plus,
+    }
+
+    def format(self, record):
+        if util.isatty():
+            formats = self.FORMATS_COLOR   # pragma: no cover
+        else:
+            formats = self.FORMATS
+
+        log_fmt = formats.get(record.levelno)
+        formatter = logging.Formatter(log_fmt)
+        return formatter.format(record)

pyaptly/main.py

@@ -5,7 +5,16 @@
 
 import tomli
 
-from . import command, mirror, publish, repo, snapshot, state_reader
+from . import (
+    command,
+    custom_logger,
+    mirror,
+    publish,
+    repo,
+    snapshot,
+    state_reader,
+    util,
+)
 
 _logging_setup = False
 
@@ -36,6 +45,12 @@ def main(argv=None):
         help="Enable debug output",
         action="store_true",
     )
+    parser.add_argument(
+        "--info",
+        "-i",
+        help="Enable info output (show executed commands)",
+        action="store_true",
+    )
     parser.add_argument(
         "--pretend",
         "-p",
@@ -64,14 +79,16 @@ def main(argv=None):
 
     args = parser.parse_args(argv)
     root = logging.getLogger()
-    formatter = logging.Formatter(
-        "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
-    )
+    formatter = custom_logger.CustomFormatter()
     if not _logging_setup:  # noqa
         handler = logging.StreamHandler(sys.stderr)
         handler.setFormatter(formatter)
         root.addHandler(handler)
-        handler.setLevel(logging.CRITICAL)
+        root.setLevel(logging.WARNING)
+        handler.setLevel(logging.WARNING)
+        if args.info:
+            root.setLevel(logging.INFO)
+            handler.setLevel(logging.INFO)
         if args.debug:
             root.setLevel(logging.DEBUG)
             handler.setLevel(logging.DEBUG)

pyaptly/tests/test_mirror.py

@@ -7,17 +7,25 @@
 
 
 @pytest.mark.parametrize("config", ["debug.toml"], indirect=True)
-def test_debug(environment, config):
+@pytest.mark.parametrize("kind", ["debug", "info"])
+def test_debug(environment, config, kind):
     """Test if debug is enabled with -d."""
+    if kind == "debug":
+        arg = "-d"
+        expect = logging.DEBUG
+    else:
+        arg = "-i"
+        expect = logging.INFO
+    main._logging_setup = False  # revert logging setup by environment fixture
     args = [
-        "-d",
+        arg,
         "-c",
         config,
         "mirror",
         "create",
     ]
     main.main(args)
-    assert logging.getLogger().level == logging.DEBUG
+    assert logging.getLogger().level == expect
 
 
 @pytest.mark.parametrize("config", ["mirror-extra.toml"], indirect=True)

pyaptly/tests/test_util.py

@@ -5,10 +5,8 @@
 
 from .. import snapshot, util
 
-EXPECT = """
-stdout:     'first
-             second'
-""".strip()
+EXPECT = """stdout:     'first
+               second'"""
 
 
 @pytest.mark.parametrize("decode", [True, False])
@@ -29,7 +27,7 @@ def test_run(test_path, debug_mode, caplog, decode, unicode_error):
     caplog.clear()
     util.run_command(["sh", "-c", "printf error 1>&2; false"], decode=decode)
     assert "stderr:     'error'" in caplog.messages[0]
-    assert "returncode: 1" in caplog.messages[0]
+    assert "-> 1" in caplog.messages[0]
     caplog.clear()
     util.run_command(["sh", "-c", "printf 'first\nsecond'"], decode=decode)
     assert EXPECT in caplog.messages[0]

pyaptly/util.py

@@ -1,9 +1,12 @@
 """Basic function like running processes and logging."""
 
 import logging
+import os
 import subprocess
 from pathlib import Path
-from subprocess import DEVNULL, PIPE, CalledProcessError  # noqa: F401
+
+from colorama import Fore, Style, init
+from subprocess import PIPE, CalledProcessError  # noqa: F401
 from typing import Optional, Sequence
 
 _DEFAULT_KEYSERVER: str = "hkps://keys.openpgp.org"
@@ -14,20 +17,30 @@
 
 RESULT_LOG = """
 Command call
-args:       {args}
-returncode: {returncode}
-stdout:     '{stdout}'
-stderr:     '{stderr}'
+  cmd:         {cmd} {color_begin}-> {returncode}{color_end}
 """.strip()
-_indent = " " * 13
+OUTPUT_LOG = "  {out_type}:     '{output}'"
+_indent = " " * 15
+
+_isatty_cache = None
+
+
+lg = logging.getLogger(__name__)
 
-logger = logging.getLogger(__name__)
+
+def isatty():
+    global _isatty_cache
+    if _isatty_cache is None:
+        _isatty_cache = os.isatty(1)
+        if _isatty_cache:
+            init()  # pragma: no cover
+    return _isatty_cache
 
 
 def unit_or_list_to_list(thingy):
-    """Ensure that a yml entry is always a list.
+    """Ensure that a toml entry is always a list.
 
-    Used to allow lists and single units in the yml file.
+    Used to allow lists and single units in the toml file.
 
     :param thingy: The data to ensure it is a list
     :type  thingy: list, tuple or other
@@ -45,36 +58,42 @@ def get_default_keyserver():
     else:
         return _DEFAULT_KEYSERVER
 
-
-def is_debug_mode():
-    """Check if we are in debug mode."""
-    return _DEBUG or _PYTEST_DEBUG
-
-
-def run_command(cmd_args: Sequence[str | Path], *, decode: bool = True, **kwargs):
+def run_command(
+    cmd_args: Sequence[str | Path],
+    *,
+    decode: bool = True,
+    hide_error: bool = False,
+    **kwargs,
+):
     """Instrumented subprocess.run for easier debugging.
 
-    By default this run command will add `encoding="UTF-8"` to kwargs. Disable
-    with `decode=False`.
+    - By default this run command will add `encoding="UTF-8"` to kwargs. Disable
+      with `decode=False`.
+    - Command that often or normally fail can also set `hide_error=True` to only
+      show them in if the loglevel is `INFO` (Logging and output in DEVELOPMENT.md)
     """
-    debug = is_debug_mode()
     added_stdout = False
     added_stderr = False
-    if debug:
-        if "stdout" not in kwargs:
-            kwargs["stdout"] = PIPE
-            added_stdout = True
-        if "stderr" not in kwargs:
-            kwargs["stderr"] = PIPE
-            added_stderr = True
+    # TODO assert PIPE or None
+    if "stdout" not in kwargs:
+        kwargs["stdout"] = PIPE
+        added_stdout = True
+    if "stderr" not in kwargs:
+        kwargs["stderr"] = PIPE
+        added_stderr = True
     result = None
     if decode and "encoding" not in kwargs:
         kwargs["encoding"] = "UTF-8"
     try:
         result = subprocess.run(cmd_args, **kwargs)
     finally:
-        if debug and result:
-            log_run_result(result)
+        if result:
+            log_msg = format_run_result(result, result.returncode)
+            if result.returncode == 0:
+                lg.info(log_msg)
+            else:
+                if not hide_error or lg.root.level <= 20:
+                    lg.error(log_msg)
             # Do not change returned result by debug mode
             if added_stdout:
                 delattr(result, "stdout")
@@ -112,15 +131,34 @@ def indent_out(output: bytes | str) -> str:
     return "\n".join(result)
 
 
-def log_run_result(result: subprocess.CompletedProcess):
-    """Log a CompletedProcess result log debug."""
-    msg = RESULT_LOG.format(
-        args=result.args,
-        returncode=result.returncode,
-        stdout=indent_out(result.stdout),
-        stderr=indent_out(result.stderr),
-    )
-    logger.debug(msg)
+def format_run_result(result: subprocess.CompletedProcess, returncode: int):
+    """Format a CompletedProcess result log."""
+    color_begin = ""
+    color_end = ""
+    if isatty():  # pragma: no cover
+        if returncode == 0:
+            color_begin = Fore.RED
+            color_end = Fore.YELLOW
+        else:
+            color_begin = Fore.YELLOW
+            color_end = Fore.RED
+    msg = [
+        RESULT_LOG.format(
+            cmd=" ".join([str(x) for x in result.args]),
+            returncode=result.returncode,
+            color_begin=color_begin,
+            color_end=color_end,
+            stdout=indent_out(result.stdout),
+            stderr=indent_out(result.stderr),
+        )
+    ]
+    for out_type, output in [("stdout", result.stdout), ("stderr", result.stderr)]:
+        output = output.strip()
+        if output:
+            output = indent_out(output)
+            msg.append(OUTPUT_LOG.format(out_type=out_type, output=output))
+        pass
+    return "\n".join(msg)
 
 
 def parse_aptly_show_command(show: str) -> dict[str, str]:

pyproject.toml

@@ -50,6 +50,7 @@ pyyaml = "^6.0.1"
 click = "^8.0.0"
 tomli = "^2.0.1"
 tomli-w = "^1.0.0"
+colorama = "^0.4.6"
 frozendict = "^2.2.0"
 
 [tool.poetry.group.dev.dependencies]