From 01985e5add089d6f8762ee2b6bbecb40b4f88c9c Mon Sep 17 00:00:00 2001 From: "Commentator2.0" Date: Wed, 7 May 2025 18:40:33 +0200 Subject: [PATCH] functional2: use loggers Use logger in favor over print statment. This is explicitly supported and encuraged by pytest, which also allows for capturing logs separate from stdout calls, which is handy for when e.g. lix code calls out to stdout to keep those differentiated from test output Change-Id: Ib88565a1663da3b77ca6b95f8edf644eafb4a99d --- tests/functional2/conftest.py | 1 + .../functional2/flakes/test_invalid_flake_lock.py | 5 +++-- tests/functional2/flakes/test_pure.py | 5 +++-- tests/functional2/pyproject.toml | 8 ++++++++ tests/functional2/store/test_evil_nars.py | 11 +++++++---- tests/functional2/testlib/fixtures/http_server.py | 6 +++++- tests/functional2/testlib/fixtures/logger.py | 15 +++++++++++++++ tests/functional2/testlib/fixtures/nix.py | 11 +++++++---- 8 files changed, 49 insertions(+), 13 deletions(-) create mode 100644 tests/functional2/testlib/fixtures/logger.py diff --git a/tests/functional2/conftest.py b/tests/functional2/conftest.py index f6c281ef6..03983e475 100644 --- a/tests/functional2/conftest.py +++ b/tests/functional2/conftest.py @@ -1,5 +1,6 @@ pytest_plugins = ( "functional2.testlib.fixtures.file_helper", "functional2.testlib.fixtures.formatter", + "functional2.testlib.fixtures.logger", "functional2.testlib.fixtures.nix", ) diff --git a/tests/functional2/flakes/test_invalid_flake_lock.py b/tests/functional2/flakes/test_invalid_flake_lock.py index 420819c64..fc8eddac5 100644 --- a/tests/functional2/flakes/test_invalid_flake_lock.py +++ b/tests/functional2/flakes/test_invalid_flake_lock.py @@ -1,10 +1,11 @@ +from logging import Logger from pathlib import Path from textwrap import dedent from functional2.testlib.fixtures.nix import Nix import re -def test_invalid_flake_lock(nix: Nix, tmp_path: Path): +def test_invalid_flake_lock(nix: Nix, tmp_path: Path, logger: Logger): flake_dir = tmp_path / "flake" flake_dir.mkdir() @@ -27,7 +28,7 @@ def test_invalid_flake_lock(nix: Nix, tmp_path: Path): cmd = nix.nix(["build"], flake=True) cmd.cwd = flake_dir res = cmd.run().expect(1) - print(res.stderr_plain) + logger.info(res.stderr_plain) error_re1 = re.compile(rf"while updating the lock file of flake 'path:{flake_dir}.+'") error_re2 = re.compile(r"while parsing the lock file at .+") diff --git a/tests/functional2/flakes/test_pure.py b/tests/functional2/flakes/test_pure.py index 2a319a72b..ff7bcb086 100644 --- a/tests/functional2/flakes/test_pure.py +++ b/tests/functional2/flakes/test_pure.py @@ -1,10 +1,11 @@ +from logging import Logger from pathlib import Path from textwrap import dedent from functional2.testlib.fixtures.nix import Nix import re -def test_purity_traversal(nix: Nix, tmp_path: Path): +def test_purity_traversal(nix: Nix, tmp_path: Path, logger: Logger): error_re = re.compile(r"error: access to absolute path '.+' is forbidden in pure eval mode") flake_dir = tmp_path / "flake" @@ -60,7 +61,7 @@ def test_purity_traversal(nix: Nix, tmp_path: Path): cmd = nix.nix(["eval", f".#bad{idx}"], flake=True) cmd.cwd = flake_dir res = cmd.run().expect(1) - print(res.stderr_plain) + logger.info(res.stderr_plain) assert error_re.search(res.stderr_plain) for idx in range(1, 6): cmd = nix.nix(["eval", f".#good{idx}"], flake=True) diff --git a/tests/functional2/pyproject.toml b/tests/functional2/pyproject.toml index 71a7c97e5..15125016f 100644 --- a/tests/functional2/pyproject.toml +++ b/tests/functional2/pyproject.toml @@ -1,2 +1,10 @@ [tool.pytest.ini_options] addopts = "-p no:xonsh" +log_cli = true +log_cli_level = "INFO" +# how the logs are being printed, default is `"%(filename)s %(lineno)d %(levelname)s %(message)s"` +# Example log: +# 2025-05-09T14:06:23Z [ INFO] [test_someting] This is a test message +# 2025-05-09T14:06:25Z [ ERROR] [test_smt_else] Some error related log +log_cli_format = "%(asctime)s [%(levelname)8s] [%(name)s] %(message)s" +log_cli_date_format = "%Y-%m-%dT%H:%M:%SZ" diff --git a/tests/functional2/store/test_evil_nars.py b/tests/functional2/store/test_evil_nars.py index c1f5ddf68..910ddb9a6 100644 --- a/tests/functional2/store/test_evil_nars.py +++ b/tests/functional2/store/test_evil_nars.py @@ -1,6 +1,7 @@ import os import unicodedata from io import BytesIO +from logging import Logger from pathlib import Path import pytest @@ -101,12 +102,12 @@ EVIL_NARS: list[tuple[str, NarItem]] = [ @pytest.mark.parametrize(("name", "nar"), EVIL_NARS) -def test_evil_nar(nix: Nix, name: str, nar: NarItem): +def test_evil_nar(nix: Nix, name: str, nar: NarItem, logger: Logger): bio = BytesIO() listener = NarListener(bio) write_with_export_header(nar, name.encode(), listener) - print(nar) + logger.info(nar) if name.startswith("valid-"): expected_rc = 0 @@ -116,10 +117,10 @@ def test_evil_nar(nix: Nix, name: str, nar: NarItem): raise ValueError("bad name", name) res = nix.nix_store(["--import"]).with_stdin(bio.getvalue()).run().expect(expected_rc) - print(res) + logger.info(res) -def test_unicode_evil_nar(nix: Nix, tmp_path: Path): +def test_unicode_evil_nar(nix: Nix, tmp_path: Path, logger: Logger): """ Depending on the filesystem in use, filenames that are equal modulo unicode normalization may hit the same file or not. @@ -147,6 +148,7 @@ def test_unicode_evil_nar(nix: Nix, tmp_path: Path): (meow_nfc, Symlink(b"meowmeow")), ] ), + logger, ) test_evil_nar( nix, @@ -158,4 +160,5 @@ def test_unicode_evil_nar(nix: Nix, tmp_path: Path): (meow_nfc, Regular(False, b"eepy")), ] ), + logger, ) diff --git a/tests/functional2/testlib/fixtures/http_server.py b/tests/functional2/testlib/fixtures/http_server.py index c3d4946d7..2cebdb4ec 100644 --- a/tests/functional2/testlib/fixtures/http_server.py +++ b/tests/functional2/testlib/fixtures/http_server.py @@ -5,6 +5,7 @@ HTTP server fixture for tests which binds to an auto-assigned port on localhost. import asyncio import contextlib import dataclasses +import logging import time import socket import threading @@ -12,6 +13,9 @@ from queue import Queue import aiohttp.web as web +logger = logging.getLogger(__name__) + + @dataclasses.dataclass class HttpServer: app: web.Application @@ -115,7 +119,7 @@ def dev_main(): app.add_routes([web.get("/", root)]) with http_server(app) as httpd: - print(f"Listening on http://[::1]:{httpd.port}") + logging.info("Listening on http://[::1]:%d", httpd.port) time.sleep(3600) diff --git a/tests/functional2/testlib/fixtures/logger.py b/tests/functional2/testlib/fixtures/logger.py new file mode 100644 index 000000000..d286654dd --- /dev/null +++ b/tests/functional2/testlib/fixtures/logger.py @@ -0,0 +1,15 @@ +import logging +from logging import Logger + +import pytest +from _pytest.fixtures import FixtureRequest + + +@pytest.fixture +def logger(request: FixtureRequest) -> Logger: + """ + Returns a logger object to use in a test function. + :param request: provide by pytest, information about where this fixture was used + :return: a logger object to use + """ + return logging.getLogger(request.function.__name__) diff --git a/tests/functional2/testlib/fixtures/nix.py b/tests/functional2/testlib/fixtures/nix.py index 5a52ba362..c893c76e2 100644 --- a/tests/functional2/testlib/fixtures/nix.py +++ b/tests/functional2/testlib/fixtures/nix.py @@ -13,6 +13,9 @@ import pytest from functional2.testlib.terminal_code_eater import eat_terminal_codes +logger = logging.getLogger(__name__) + + @dataclasses.dataclass class CommandResult: cmd: list[str] @@ -25,8 +28,8 @@ class CommandResult: def ok(self) -> "CommandResult": if self.rc != 0: - print("stdout: %s", self.stderr_s) - print("stderr: %s", self.stderr_s) + logger.debug("stdout: %s", self.stderr_s) + logger.debug("stderr: %s", self.stderr_s) raise subprocess.CalledProcessError( returncode=self.rc, cmd=self.cmd, stderr=self.stderr, output=self.stdout ) @@ -34,8 +37,8 @@ class CommandResult: def expect(self, rc: int) -> "CommandResult": if self.rc != rc: - print("stdout: %s", self.stderr_s) - print("stderr: %s", self.stderr_s) + logger.debug("stdout: %s", self.stderr_s) + logger.debug("stderr: %s", self.stderr_s) raise subprocess.CalledProcessError( returncode=self.rc, cmd=self.cmd, stderr=self.stderr, output=self.stdout )