Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
16 changes: 14 additions & 2 deletions src/aignostics_foundry_core/log.py
Original file line number Diff line number Diff line change
Expand Up @@ -74,7 +74,19 @@ def _validate_file_name(file_name: str | None) -> str | None:


class InterceptHandler(logging.Handler):
"""Stdlib logging handler that redirects all records to loguru."""
"""Stdlib logging handler that redirects all records to loguru.

Context propagation: loguru's ``contextualize()`` variables are carried
across ``await`` boundaries and into ``asyncio.to_thread`` workers (which
copies the contextvars context automatically). They are **not** propagated
into bare ``threading.Thread`` or ``ThreadPoolExecutor`` workers — libraries
that self-spawn threads must copy the context explicitly.

Extra merge semantics: the intercepted stdlib record's own ``extra`` dict
(set via ``logging.getLogger(...).warning(msg, extra={...})``) is merged on
top of loguru's assembled context with ``.update()``, so log-site intent
wins on the rare key collision between stdlib ``extra`` and ambient context.
"""

def emit(self, record: logging.LogRecord) -> None: # noqa: PLR6301
"""Emit a log record by forwarding it to loguru.
Expand All @@ -94,7 +106,7 @@ def emit(self, record: logging.LogRecord) -> None: # noqa: PLR6301
# Patch the record to use the original logger name, function, and line from standard logging
def patcher(record_dict: "Record") -> None:
record_dict["module"] = record.module
record_dict["extra"] = record.__dict__.get("extra", {})
record_dict["extra"].update(record.__dict__.get("extra", {}))
if record.processName and record.process:
record_dict["process"].id = record.process
record_dict["process"].name = record.processName
Expand Down
75 changes: 75 additions & 0 deletions tests/aignostics_foundry_core/log_test.py
Original file line number Diff line number Diff line change
Expand Up @@ -3,19 +3,27 @@
import logging as stdlib_logging
import sys
from pathlib import Path
from typing import TYPE_CHECKING, Any

import pytest
from pydantic import ValidationError

from aignostics_foundry_core.log import InterceptHandler, LogSettings, logging_initialize
from tests.conftest import TEST_PROJECT_PREFIX

if TYPE_CHECKING:
from loguru import Message

_MARKER_MESSAGE = "log_test_unique_marker_4f2a"
_STDLIB_MESSAGE = "stdlib_redirect_unique_marker_9b3c"
_FILE_HANDLER_MARKER = "file_handler_unique_marker_7e9b"
_FILTER_MARKER = "filter_func_unique_marker_3d5f"
_REPLACE_MARKER = "replace_handlers_unique_marker_8c1a"
_SENTRY_MARKER = "sentry.io unique drop marker 2f4e"
_CONTEXTUALIZE_JOB_ID = "test_job_id_context_8f3c"
_CONTEXTUALIZE_MARKER = "contextualize_intercept_marker_6d2e"
_PARITY_NATIVE_MARKER = "parity_native_loguru_4b7a"
_PARITY_STDLIB_MARKER = "parity_stdlib_intercept_9c1f"


@pytest.mark.sequential
Expand Down Expand Up @@ -117,6 +125,73 @@ def test_logging_initialize_respects_env_prefix_from_context(
logger.info(_MARKER_MESSAGE)
assert _MARKER_MESSAGE not in capsys.readouterr().err

def test_intercept_handler_preserves_contextualize_extra(self) -> None:
"""Stdlib log emitted inside logger.contextualize() carries the bound context fields."""
from loguru import logger

logging_initialize()
records: list[Any] = []

def capture(message: "Message") -> None:
records.append(message.record)

sink_id = logger.add(capture, level="DEBUG")
try:
with logger.contextualize(job_id=_CONTEXTUALIZE_JOB_ID):
stdlib_logging.getLogger("test.ctx.intercept").warning(_CONTEXTUALIZE_MARKER)
finally:
logger.remove(sink_id)

intercepted = [r for r in records if _CONTEXTUALIZE_MARKER in r["message"]]
assert intercepted, "No intercepted record captured"
assert intercepted[0]["extra"]["job_id"] == _CONTEXTUALIZE_JOB_ID

def test_intercept_handler_preserves_base_context_extra(self) -> None:
"""Intercepted stdlib records retain base-config keys set by logging_initialize()."""
from loguru import logger

logging_initialize()
records: list[Any] = []

def capture(message: "Message") -> None:
records.append(message.record)

sink_id = logger.add(capture, level="DEBUG")
try:
with logger.contextualize(job_id=_CONTEXTUALIZE_JOB_ID):
stdlib_logging.getLogger("test.ctx.base").warning(_CONTEXTUALIZE_MARKER)
finally:
logger.remove(sink_id)

intercepted = [r for r in records if _CONTEXTUALIZE_MARKER in r["message"]]
assert intercepted, "No intercepted record captured"
assert "project_name" in intercepted[0]["extra"]
assert "version" in intercepted[0]["extra"]

def test_intercept_handler_extra_matches_native_loguru(self) -> None:
"""Native loguru and intercepted stdlib lines share the same context fields."""
from loguru import logger

logging_initialize()
records: list[Any] = []

def capture(message: "Message") -> None:
records.append(message.record)

sink_id = logger.add(capture, level="DEBUG")
try:
with logger.contextualize(job_id=_CONTEXTUALIZE_JOB_ID):
logger.warning(_PARITY_NATIVE_MARKER)
stdlib_logging.getLogger("test.ctx.parity").warning(_PARITY_STDLIB_MARKER)
finally:
logger.remove(sink_id)

native = [r for r in records if _PARITY_NATIVE_MARKER in r["message"]]
stdlib = [r for r in records if _PARITY_STDLIB_MARKER in r["message"]]
assert native, "No native loguru record captured"
assert stdlib, "No intercepted stdlib record captured"
assert native[0]["extra"]["job_id"] == stdlib[0]["extra"]["job_id"] == _CONTEXTUALIZE_JOB_ID


@pytest.mark.unit
class TestLogSettings:
Expand Down
Loading