diff --git a/DEVELOPMENT.md b/DEVELOPMENT.md new file mode 100644 index 0000000..acb3e93 --- /dev/null +++ b/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`. diff --git a/README.md b/README.md index 6b66302..94ccd94 100644 --- a/README.md +++ b/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 ::::::::::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 ::::::::::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. diff --git a/poetry.lock b/poetry.lock index c39967d..c1da10f 100644 --- a/poetry.lock +++ b/poetry.lock @@ -366,13 +366,13 @@ files = [ [[package]] name = "hypothesis" -version = "6.98.15" +version = "6.98.17" description = "A library for property-based testing" optional = false python-versions = ">=3.8" files = [ - {file = "hypothesis-6.98.15-py3-none-any.whl", hash = "sha256:5b40fd81fce9e0b35f0a47e10eb41f375a6b9e8551d0e1084c83b8b0d0d1bb6b"}, - {file = "hypothesis-6.98.15.tar.gz", hash = "sha256:1e31210951511b24ce8b3b6e04d791c466385a30ac3af571bf2223954b025d77"}, + {file = "hypothesis-6.98.17-py3-none-any.whl", hash = "sha256:313f64b9f9f95e12c8b5342466bef7f352d2608afeeb434817c039602b45f0c4"}, + {file = "hypothesis-6.98.17.tar.gz", hash = "sha256:bbd227000cc21a9686a00867f031479c3812d8ab076e4af1c813f6b3a50c98f5"}, ] [package.dependencies] @@ -1228,4 +1228,4 @@ test = ["pytest"] [metadata] lock-version = "2.0" python-versions = "^3.11" -content-hash = "4d57210cb742dc4897ab952e868dd82e79ade4ddff1bb13a9dbe50fef19c0989" +content-hash = "7df789fe9c27a5df9b3024d115fad7579b3c3f0e8323ed812a3390034e2452df" diff --git a/pyaptly/command.py b/pyaptly/command.py index 12bbfc2..89a2451 100644 --- a/pyaptly/command.py +++ b/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 diff --git a/pyaptly/custom_logger.py b/pyaptly/custom_logger.py new file mode 100644 index 0000000..c0b25d1 --- /dev/null +++ b/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) diff --git a/pyaptly/main.py b/pyaptly/main.py index f1319cf..e249b8b 100755 --- a/pyaptly/main.py +++ b/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) diff --git a/pyaptly/tests/test_util.py b/pyaptly/tests/test_util.py index f6f8089..94f8698 100644 --- a/pyaptly/tests/test_util.py +++ b/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] diff --git a/pyaptly/util.py b/pyaptly/util.py index 64a041a..dc69062 100644 --- a/pyaptly/util.py +++ b/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]: diff --git a/pyproject.toml b/pyproject.toml index 16ce05a..8cdea05 100644 --- a/pyproject.toml +++ b/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]