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,5 +1,6 @@
 pytest_plugins = (
     "functional2.testlib.fixtures.file_helper",
     "functional2.testlib.fixtures.formatter",
+    "functional2.testlib.fixtures.logger",
     "functional2.testlib.fixtures.nix",
 )

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 .+")

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)

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"

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,
     )

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)
 
 

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__)

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
             )