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
+ 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_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()
+ 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():
+ 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]