Clean release snapshot

tests/test_logging_setup.py

@@ -0,0 +1,507 @@
+"""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 slopsmith 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("slopsmith")
+    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("slopsmith.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("slopsmith").handlers:
+        if isinstance(h, logging.StreamHandler) and not isinstance(
+            h, logging.FileHandler
+        ):
+            h.stream = buf
+
+    test_log = logging.getLogger("slopsmith.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 / "slopsmith.log"
+    monkeypatch.setenv("LOG_FORMAT", "json")
+    monkeypatch.setenv("LOG_LEVEL", "DEBUG")
+    monkeypatch.setenv("LOG_FILE", str(log_path))
+    logging_setup.configure_logging()
+
+    logging.getLogger("slopsmith.filelog").info("written_to_file")
+
+    # Flush all file handlers so the write is committed.
+    for h in logging.getLogger("slopsmith").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" / "slopsmith.log"
+    monkeypatch.setenv("LOG_FORMAT", "json")
+    monkeypatch.setenv("LOG_LEVEL", "DEBUG")
+    monkeypatch.setenv("LOG_FILE", str(log_path))
+    logging_setup.configure_logging()
+
+    logging.getLogger("slopsmith.nested").info("nested_dir_event")
+
+    for h in logging.getLogger("slopsmith").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 / "slopsmith.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("slopsmith")
+    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 / "slopsmith.log"
+    monkeypatch.setenv("LOG_FORMAT", "text")
+    monkeypatch.setenv("LOG_LEVEL", "DEBUG")
+    monkeypatch.setenv("LOG_FILE", str(log_path))
+    logging_setup.configure_logging()
+
+    logging.getLogger("slopsmith.plain").info("plain_text_event")
+
+    for h in logging.getLogger("slopsmith").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 / "slopsmith.log"
+    monkeypatch.setenv("LOG_FORMAT", "json")
+    monkeypatch.setenv("LOG_LEVEL", "DEBUG")
+    monkeypatch.setenv("LOG_FILE", str(log_path))
+    logging_setup.configure_logging()
+
+    logging.getLogger("slopsmith.jsonfile").warning("json_file_event")
+
+    for h in logging.getLogger("slopsmith").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("slopsmith").handlers:
+        if isinstance(h, logging.StreamHandler) and not isinstance(
+            h, logging.FileHandler
+        ):
+            h.stream = buf
+
+    log = logging.getLogger("slopsmith.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("slopsmith").handlers:
+        if isinstance(h, logging.StreamHandler) and not isinstance(
+            h, logging.FileHandler
+        ):
+            h.stream = buf
+
+    log = logging.getLogger("slopsmith.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("slopsmith").handlers:
+        if isinstance(h, logging.StreamHandler) and not isinstance(
+            h, logging.FileHandler
+        ):
+            h.stream = buf
+
+    logging.getLogger("slopsmith.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"
+    )