"""Tests for lib/logging_setup.py — configure_logging() behaviour. Covers: - LOG_FORMAT=json produces one valid JSON object per line. - JSON output includes expected fields (event, level, timestamp). - exc_info / logger.exception() is serializable in JSON mode (no TypeError). - LOG_LEVEL=WARNING suppresses INFO records. - LOG_LEVEL=WARNING allows WARNING records. - LOG_FORMAT=text produces non-JSON human-readable output. - Correlation ID context variable is injected as request_id in JSON mode. - Calling configure_logging() again with a new LOG_LEVEL takes effect. - LOG_FILE creates a RotatingFileHandler that writes log records. - LOG_FILE + LOG_FORMAT=text file output contains no ANSI escape sequences. - LOG_FILE + LOG_FORMAT=json file output is valid JSON. - Unrecognised LOG_LEVEL value falls back to INFO with a stderr warning. - Unrecognised LOG_FORMAT value falls back to text mode with a stderr warning. - configure_logging() restores structlog handlers on uvicorn loggers after uvicorn applies its own default log_config (simulates startup re-configuration). """ import io import json import logging import pytest import structlog # --------------------------------------------------------------------------- # Fixtures # --------------------------------------------------------------------------- @pytest.fixture(autouse=True) def _isolate_logging(isolate_logging): """Auto-use wrapper that pulls in the shared isolate_logging fixture.""" def _setup(monkeypatch, *, fmt: str = "json", level: str = "DEBUG") -> tuple: """Configure logging with the given env vars and return (logger, capture_buf). Returns a stdlib logger under the feedBack hierarchy and a StringIO buffer wired to the console handler's stream. """ monkeypatch.setenv("LOG_FORMAT", fmt) monkeypatch.setenv("LOG_LEVEL", level) monkeypatch.delenv("LOG_FILE", raising=False) import logging_setup logging_setup.configure_logging() buf = io.StringIO() root = logging.getLogger("feedBack") for h in root.handlers: # Replace stream on the console StreamHandler (not file handlers). if isinstance(h, logging.StreamHandler) and not isinstance( h, logging.FileHandler ): h.stream = buf return logging.getLogger("feedBack.test"), buf # --------------------------------------------------------------------------- # JSON format # --------------------------------------------------------------------------- def test_json_format_emits_valid_json(monkeypatch): log, buf = _setup(monkeypatch, fmt="json") log.info("hello_world") line = buf.getvalue().strip() assert line, "no output was captured" parsed = json.loads(line) assert parsed.get("event") == "hello_world" def test_json_format_includes_level_field(monkeypatch): log, buf = _setup(monkeypatch, fmt="json") log.warning("check_level") parsed = json.loads(buf.getvalue().strip()) assert "level" in parsed def test_json_format_includes_timestamp_field(monkeypatch): log, buf = _setup(monkeypatch, fmt="json") log.info("ts_test") parsed = json.loads(buf.getvalue().strip()) assert "timestamp" in parsed def test_json_format_exc_info_is_serializable(monkeypatch): """exc_info tuples must not raise TypeError in JSONRenderer.""" log, buf = _setup(monkeypatch, fmt="json") try: raise ValueError("boom") except ValueError: log.exception("oops") line = buf.getvalue().strip() assert line, "no output was captured" # Must be valid JSON — no TypeError should have propagated. parsed = json.loads(line) assert parsed.get("event") == "oops" # --------------------------------------------------------------------------- # LOG_LEVEL filtering # --------------------------------------------------------------------------- def test_log_level_warning_suppresses_info(monkeypatch): log, buf = _setup(monkeypatch, fmt="json", level="WARNING") log.info("should_be_suppressed") assert buf.getvalue() == "" def test_log_level_warning_allows_warning(monkeypatch): log, buf = _setup(monkeypatch, fmt="json", level="WARNING") log.warning("visible") assert buf.getvalue().strip() != "" # --------------------------------------------------------------------------- # Text format # --------------------------------------------------------------------------- def test_text_format_is_not_json(monkeypatch): log, buf = _setup(monkeypatch, fmt="text") log.info("hello_text") line = buf.getvalue().strip() assert line != "" with pytest.raises((json.JSONDecodeError, ValueError)): json.loads(line) # --------------------------------------------------------------------------- # Correlation ID # --------------------------------------------------------------------------- def test_correlation_id_injected_when_set(monkeypatch): """request_id appears in the event dict when the correlation_id context var is set.""" from asgi_correlation_id import correlation_id log, buf = _setup(monkeypatch, fmt="json") token = correlation_id.set("test-req-id-abc") try: log.info("correlated_event") finally: correlation_id.reset(token) parsed = json.loads(buf.getvalue().strip()) assert parsed.get("request_id") == "test-req-id-abc" def test_no_request_id_when_correlation_id_not_set(monkeypatch): """request_id is absent when no correlation_id context var is set.""" log, buf = _setup(monkeypatch, fmt="json") log.info("uncorrelated_event") parsed = json.loads(buf.getvalue().strip()) assert "request_id" not in parsed # --------------------------------------------------------------------------- # Reconfiguration # --------------------------------------------------------------------------- def test_reconfigure_picks_up_new_level(monkeypatch): """A second configure_logging() call reflects the updated LOG_LEVEL.""" import logging_setup monkeypatch.setenv("LOG_FORMAT", "json") monkeypatch.setenv("LOG_LEVEL", "DEBUG") monkeypatch.delenv("LOG_FILE", raising=False) logging_setup.configure_logging() # Raise the level to WARNING via a second call. monkeypatch.setenv("LOG_LEVEL", "WARNING") logging_setup.configure_logging() buf = io.StringIO() for h in logging.getLogger("feedBack").handlers: if isinstance(h, logging.StreamHandler) and not isinstance( h, logging.FileHandler ): h.stream = buf test_log = logging.getLogger("feedBack.reconfig") test_log.info("should_not_appear") assert buf.getvalue() == "", "INFO should be suppressed after reconfigure to WARNING" test_log.warning("should_appear") assert buf.getvalue().strip() != "", "WARNING should pass through" # --------------------------------------------------------------------------- # LOG_FILE # --------------------------------------------------------------------------- def test_log_file_creates_rotating_handler(monkeypatch, tmp_path): """LOG_FILE wires up a RotatingFileHandler that writes log records.""" import logging_setup log_path = tmp_path / "feedBack.log" monkeypatch.setenv("LOG_FORMAT", "json") monkeypatch.setenv("LOG_LEVEL", "DEBUG") monkeypatch.setenv("LOG_FILE", str(log_path)) logging_setup.configure_logging() logging.getLogger("feedBack.filelog").info("written_to_file") # Flush all file handlers so the write is committed. for h in logging.getLogger("feedBack").handlers: h.flush() assert log_path.exists(), "log file was not created" content = log_path.read_text(encoding="utf-8").strip() assert content, "log file is empty" parsed = json.loads(content) assert parsed.get("event") == "written_to_file" def test_log_file_creates_parent_dirs(monkeypatch, tmp_path): """LOG_FILE auto-creates missing parent directories instead of raising.""" import logging_setup log_path = tmp_path / "nested" / "deeper" / "feedBack.log" monkeypatch.setenv("LOG_FORMAT", "json") monkeypatch.setenv("LOG_LEVEL", "DEBUG") monkeypatch.setenv("LOG_FILE", str(log_path)) logging_setup.configure_logging() logging.getLogger("feedBack.nested").info("nested_dir_event") for h in logging.getLogger("feedBack").handlers: h.flush() assert log_path.exists(), "log file was not created in nested directories" def test_log_file_bad_path_falls_back_gracefully(monkeypatch, tmp_path, capsys): """An unwritable LOG_FILE path must not crash the server; a warning is printed.""" import logging_setup # Point LOG_FILE at an existing regular file used as the "parent" so that # mkdir() and open() will both fail (we can't write to a path whose # parent is a file, not a directory). blocker = tmp_path / "blocker" blocker.write_text("I am a file, not a directory") bad_path = str(blocker / "feedBack.log") monkeypatch.setenv("LOG_FORMAT", "json") monkeypatch.setenv("LOG_LEVEL", "DEBUG") monkeypatch.setenv("LOG_FILE", bad_path) # Must not raise — server should start with console-only logging. logging_setup.configure_logging() captured = capsys.readouterr() assert "WARNING" in captured.err assert "LOG_FILE" in captured.err # Console logging still works. root = logging.getLogger("feedBack") file_handlers = [h for h in root.handlers if isinstance(h, logging.FileHandler)] assert not file_handlers, "no FileHandler should have been added after open failure" def test_log_file_text_mode_no_ansi(monkeypatch, tmp_path): """LOG_FILE with LOG_FORMAT=text must not write ANSI escape sequences.""" import logging_setup log_path = tmp_path / "feedBack.log" monkeypatch.setenv("LOG_FORMAT", "text") monkeypatch.setenv("LOG_LEVEL", "DEBUG") monkeypatch.setenv("LOG_FILE", str(log_path)) logging_setup.configure_logging() logging.getLogger("feedBack.plain").info("plain_text_event") for h in logging.getLogger("feedBack").handlers: h.flush() content = log_path.read_text(encoding="utf-8") # ANSI escape sequences start with ESC (\x1b) followed by [. assert "\x1b[" not in content, "file output must not contain ANSI escape sequences" assert "plain_text_event" in content def test_log_file_json_mode_is_valid_json(monkeypatch, tmp_path): """LOG_FILE with LOG_FORMAT=json writes one valid JSON object per line.""" import logging_setup log_path = tmp_path / "feedBack.log" monkeypatch.setenv("LOG_FORMAT", "json") monkeypatch.setenv("LOG_LEVEL", "DEBUG") monkeypatch.setenv("LOG_FILE", str(log_path)) logging_setup.configure_logging() logging.getLogger("feedBack.jsonfile").warning("json_file_event") for h in logging.getLogger("feedBack").handlers: h.flush() lines = [l for l in log_path.read_text(encoding="utf-8").splitlines() if l.strip()] assert lines, "no output written to log file" parsed = json.loads(lines[0]) assert parsed.get("event") == "json_file_event" # --------------------------------------------------------------------------- # Typo / misconfiguration warnings # --------------------------------------------------------------------------- def test_bad_log_level_falls_back_to_info_with_warning(monkeypatch, capsys): """An unrecognised LOG_LEVEL falls back to INFO and emits a stderr warning.""" import logging_setup monkeypatch.setenv("LOG_LEVEL", "TYPO") monkeypatch.setenv("LOG_FORMAT", "json") monkeypatch.delenv("LOG_FILE", raising=False) logging_setup.configure_logging() # Warning must appear on stderr. err = capsys.readouterr().err assert "LOG_LEVEL" in err assert "TYPO" in err # Fallback to INFO: INFO records pass through, DEBUG does not. buf = io.StringIO() for h in logging.getLogger("feedBack").handlers: if isinstance(h, logging.StreamHandler) and not isinstance( h, logging.FileHandler ): h.stream = buf log = logging.getLogger("feedBack.typo_level") log.debug("should_be_filtered") assert buf.getvalue() == "", "DEBUG should be suppressed when level is INFO" log.info("should_pass") assert buf.getvalue().strip() != "", "INFO should pass through at default level" def test_non_integer_log_level_attribute_falls_back_to_info(monkeypatch, capsys): """LOG_LEVEL set to a non-integer logging module attribute (e.g. BASIC_FORMAT) must fall back to INFO rather than passing a string to setLevel().""" import logging_setup # logging.BASIC_FORMAT is a real attribute on the logging module but its # value is a string ('%(levelname)s:%(name)s:%(message)s'), not an int. # The old `getattr(...) is None` guard would silently accept it and then # crash inside setLevel(); the new isinstance(level, int) guard must catch it. monkeypatch.setenv("LOG_LEVEL", "BASIC_FORMAT") monkeypatch.setenv("LOG_FORMAT", "json") monkeypatch.delenv("LOG_FILE", raising=False) # Must not raise even though BASIC_FORMAT is a str, not an int. logging_setup.configure_logging() err = capsys.readouterr().err assert "LOG_LEVEL" in err assert "BASIC_FORMAT" in err # Verify INFO-level fallback: DEBUG suppressed, INFO passes. buf = io.StringIO() for h in logging.getLogger("feedBack").handlers: if isinstance(h, logging.StreamHandler) and not isinstance( h, logging.FileHandler ): h.stream = buf log = logging.getLogger("feedBack.basic_format_level") log.debug("should_be_filtered") assert buf.getvalue() == "", "DEBUG should be suppressed when level fell back to INFO" log.info("should_pass") assert buf.getvalue().strip() != "", "INFO should pass through at fallback level" def test_bad_log_format_falls_back_to_text_with_warning(monkeypatch, capsys): """An unrecognised LOG_FORMAT falls back to text mode and emits a stderr warning.""" import logging_setup monkeypatch.setenv("LOG_FORMAT", "xml") monkeypatch.setenv("LOG_LEVEL", "DEBUG") monkeypatch.delenv("LOG_FILE", raising=False) logging_setup.configure_logging() err = capsys.readouterr().err assert "LOG_FORMAT" in err assert "xml" in err # Text fallback: output should not be JSON. buf = io.StringIO() for h in logging.getLogger("feedBack").handlers: if isinstance(h, logging.StreamHandler) and not isinstance( h, logging.FileHandler ): h.stream = buf logging.getLogger("feedBack.typo_fmt").info("text_fallback_event") line = buf.getvalue().strip() assert line, "no output captured" with pytest.raises((json.JSONDecodeError, ValueError)): json.loads(line) # --------------------------------------------------------------------------- # Uvicorn log_config override resilience # --------------------------------------------------------------------------- def test_configure_logging_survives_uvicorn_log_config_reset(monkeypatch): """configure_logging() must restore structlog handlers after uvicorn resets them. When uvicorn starts, it calls logging.config.dictConfig(LOGGING_CONFIG) which replaces the handlers on the uvicorn* loggers that configure_logging() set at import time. The startup_events() handler in server.py re-calls configure_logging() to restore the structlog pipeline. This test simulates that sequence without launching a real uvicorn process. """ import logging.config import logging_setup import structlog monkeypatch.setenv("LOG_FORMAT", "json") monkeypatch.setenv("LOG_LEVEL", "DEBUG") monkeypatch.delenv("LOG_FILE", raising=False) # Step 1: configure_logging() as done at server.py import time. logging_setup.configure_logging() # Verify: uvicorn logger now uses our ProcessorFormatter. uvicorn_logger = logging.getLogger("uvicorn") assert uvicorn_logger.handlers, "uvicorn logger should have handlers after configure_logging()" assert isinstance( uvicorn_logger.handlers[0].formatter, structlog.stdlib.ProcessorFormatter, ), "uvicorn handler should use ProcessorFormatter before uvicorn startup" # Step 2: simulate uvicorn applying its own LOGGING_CONFIG (as it does on startup). from uvicorn.config import LOGGING_CONFIG as _UVICORN_LOG_CFG logging.config.dictConfig(_UVICORN_LOG_CFG) # After uvicorn's dictConfig, uvicorn logger handlers are replaced. uvicorn_handlers_after_uvicorn = logging.getLogger("uvicorn").handlers for h in uvicorn_handlers_after_uvicorn: assert not isinstance(h.formatter, structlog.stdlib.ProcessorFormatter), ( "uvicorn reset should have replaced our ProcessorFormatter — " "test setup incorrect" ) # Step 3: re-call configure_logging() as startup_events() in server.py does. logging_setup.configure_logging() # Verify: structlog pipeline is restored on all uvicorn* loggers. for name in ("uvicorn", "uvicorn.error", "uvicorn.access"): lg = logging.getLogger(name) assert lg.handlers, f"{name!r} logger has no handlers after re-configure" assert isinstance( lg.handlers[0].formatter, structlog.stdlib.ProcessorFormatter, ), ( f"{name!r} handler formatter is {type(lg.handlers[0].formatter).__name__!r};" " expected ProcessorFormatter after startup re-configure" ) # --------------------------------------------------------------------------- # main.py entry point # --------------------------------------------------------------------------- def test_main_run_passes_log_config_none(): """main.py's run() must pass log_config=None to uvicorn.run(). Passing log_config=None prevents uvicorn from calling logging.config.dictConfig(LOGGING_CONFIG) during startup, so the structlog pipeline installed by configure_logging() is never overwritten. This is what ensures early lifecycle messages like "Started server process" pass through the structured formatter rather than uvicorn's stock one. """ import unittest.mock import main with ( unittest.mock.patch("logging_setup.configure_logging") as mock_cfg, unittest.mock.patch("uvicorn.run") as mock_run, ): main.run() mock_cfg.assert_called_once() mock_run.assert_called_once() kwargs = mock_run.call_args.kwargs assert "log_config" in kwargs, ( "main.run() must explicitly pass log_config= to uvicorn.run()" ) assert kwargs["log_config"] is None, ( "main.run() must pass log_config=None to prevent uvicorn from " "overwriting our structlog handlers" )