fix: normalize Rust-emitted log record tags in openjd.sessions._v1

src/openjd/sessions/_v1/_logging.py

@@ -2,33 +2,16 @@
 from __future__ import annotations
 
 from typing import Any, MutableMapping, TypedDict
-from enum import Flag, auto
 import logging
 
-__all__ = ["LOG", "LoggerAdapter", "LogExtraInfo", "LogContent"]
-
+from .._logging import LogContent
 
-class LogContent(Flag):
-    """
-    A Flag Enum which describes the content of a log record.
-    """
+__all__ = ["LOG", "LoggerAdapter", "LogExtraInfo", "LogContent"]
 
-    BANNER = auto()  # Logs which contain a banner, such as to visually seperate log sections
-    FILE_PATH = auto()  # Logs which contain a filepath
-    FILE_CONTENTS = auto()  # Logs which contain the contents of a file
-    COMMAND_OUTPUT = auto()  # Logs which contain the output of a command run
-    EXCEPTION_INFO = (
-        auto()
-    )  # Logs which contain an exception openjd encountered, potentially including sensitive information such as filepaths or host information.
-    PROCESS_CONTROL = (
-        auto()
-    )  # Logs which contain information related to starting, killing, or signalling processes.
-    PARAMETER_INFO = (
-        auto()
-    )  # Logs which contain details about parameters and their values pertaining to the running action
-    HOST_INFO = (
-        auto()
-    )  # Logs which contain details about the system environment, e.g. dependency versions, OS name, CPU architecture.
+# LogContent is the public openjd.sessions.LogContent class, not a second Flag enum
+# with the same members. Consumers route records on the LOG logger by type-checking
+# `record.openjd_log_content` against openjd.sessions.LogContent, and enum.Flag
+# comparisons are class-scoped, so a duplicate class would fail that check.
 
 
 class LogExtraInfo(TypedDict):
@@ -82,9 +65,59 @@ def process(
 If the LogRecord does not have the "openjd_log_content" no guarantees are made as to what content
 is in the LogRecord. LogRecords that contain LogContent.EXECPTION_INFO may also transitively include
 potentially sensitive information like filepaths or host info due to the nature of exception messages.
+
+LogRecords emitted by the Rust-backed session runtime additionally carry a "session_id" (str) and
+an "openjd_timestamp_usec" (int). pyo3-log delivers all structured fields to Python as strings, so
+importing openjd.sessions._v1 installs a filter on this logger that converts "openjd_log_content"
+back to a LogContent and "openjd_timestamp_usec" back to an int before any handler sees the record.
 """
 LOG.setLevel(logging.INFO)
 
+
+class _RustLogRecordNormalizingFilter(logging.Filter):
+    """Restores the Python types of the structured fields on Rust-emitted records.
+
+    The Rust session runtime tags each record it emits with ``session_id`` (str),
+    ``openjd_log_content`` (a LogContent bitmask as an unsigned integer) and
+    ``openjd_timestamp_usec`` (unsigned integer). pyo3-log renders every value
+    with its Rust ``Display`` and passes the strings as ``extra`` to
+    ``Logger.makeRecord``, so ``openjd_log_content`` arrives as e.g. "8" and the
+    timestamp as a decimal string; pyo3-log has no hook to keep the types.
+
+    Installed on the logger, not on a handler: pyo3-log delivers records with
+    ``Logger.handle()``, which runs the logger's filters before any handler (and
+    any handler-level filter) sees the record. Values this LogContent cannot
+    represent (e.g. a bit added by a newer runtime) are left as they arrived.
+    The filter never drops a record.
+    """
+
+    def filter(self, record: logging.LogRecord) -> bool:
+        # Rust formats these unsigned integers as plain decimal digits. Only
+        # convert that form: int() would also accept signs and whitespace, and
+        # a negative value would become a LogContent complement rather than an
+        # error.
+        content = getattr(record, "openjd_log_content", None)
+        if isinstance(content, str) and content.isdigit():
+            try:
+                setattr(record, "openjd_log_content", LogContent(int(content)))
+            except ValueError:
+                pass
+        timestamp = getattr(record, "openjd_timestamp_usec", None)
+        if isinstance(timestamp, str) and timestamp.isdigit():
+            setattr(record, "openjd_timestamp_usec", int(timestamp))
+        return True
+
+
+def _install_rust_log_record_normalizing_filter(logger: logging.Logger) -> None:
+    """Install one _RustLogRecordNormalizingFilter on ``logger``; idempotent."""
+    if not any(isinstance(f, _RustLogRecordNormalizingFilter) for f in logger.filters):
+        logger.addFilter(_RustLogRecordNormalizingFilter())
+
+
+# openjd.sessions._v1 imports this module before the modules that load the Rust
+# extension, so the filter is in place before the runtime emits its first record.
+_install_rust_log_record_normalizing_filter(LOG)
+
 _banner_log_extra = LogExtraInfo(openjd_log_content=LogContent.BANNER)
 
 

test/openjd/sessions_v1/test_logging.py

@@ -0,0 +1,268 @@
+# Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved.
+
+"""Tests for the openjd.sessions._v1 logging module.
+
+The subject under test is the filter that ``openjd.sessions._v1._logging``
+installs on the "openjd.sessions" logger. pyo3-log delivers the Rust session
+runtime's structured log fields to Python as strings, so ``openjd_log_content``
+arrives as a decimal bitmask string such as "8" and ``openjd_timestamp_usec`` as
+a decimal string; the filter restores the documented Python types.
+"""
+
+from __future__ import annotations
+
+import logging
+import uuid
+from typing import Any, Iterator
+
+import pytest
+
+import openjd.sessions
+import openjd.sessions._v1
+from openjd.sessions import LogContent
+from openjd.sessions._v1._logging import (
+    LOG,
+    _RustLogRecordNormalizingFilter,
+    _install_rust_log_record_normalizing_filter,
+)
+
+
+def _record(**extra: Any) -> logging.LogRecord:
+    return logging.makeLogRecord(
+        {
+            "name": LOG.name,
+            "msg": "message",
+            "levelno": logging.INFO,
+            "levelname": "INFO",
+            **extra,
+        }
+    )
+
+
+class _CollectingHandler(logging.Handler):
+    def __init__(self) -> None:
+        super().__init__(level=logging.DEBUG)
+        self.records: list[logging.LogRecord] = []
+
+    def emit(self, record: logging.LogRecord) -> None:
+        self.records.append(record)
+
+
+@pytest.fixture
+def log_filter() -> _RustLogRecordNormalizingFilter:
+    return _RustLogRecordNormalizingFilter()
+
+
+class TestNormalizingFilterLogContent:
+    @pytest.mark.parametrize(
+        "value, expected",
+        [
+            *[(str(member.value), member) for member in LogContent],
+            ("10", LogContent.FILE_PATH | LogContent.COMMAND_OUTPUT),
+            ("0", LogContent(0)),
+        ],
+    )
+    def test_decimal_string_becomes_log_content(
+        self, log_filter: _RustLogRecordNormalizingFilter, value: str, expected: LogContent
+    ) -> None:
+        # GIVEN
+        record = _record(openjd_log_content=value)
+
+        # WHEN
+        result = log_filter.filter(record)
+
+        # THEN
+        assert result is True
+        assert record.openjd_log_content is expected  # type: ignore[attr-defined]
+        assert type(record.openjd_log_content) is openjd.sessions.LogContent  # type: ignore[attr-defined]
+
+    def test_already_typed_value_is_left_alone(
+        self, log_filter: _RustLogRecordNormalizingFilter
+    ) -> None:
+        # GIVEN
+        record = _record(openjd_log_content=LogContent.BANNER)
+
+        # WHEN
+        log_filter.filter(record)
+
+        # THEN
+        assert record.openjd_log_content is LogContent.BANNER  # type: ignore[attr-defined]
+
+    def test_missing_attribute_is_not_added(
+        self, log_filter: _RustLogRecordNormalizingFilter
+    ) -> None:
+        # GIVEN
+        record = _record()
+
+        # WHEN
+        log_filter.filter(record)
+
+        # THEN
+        assert not hasattr(record, "openjd_log_content")
+        assert not hasattr(record, "openjd_timestamp_usec")
+
+    @pytest.mark.parametrize(
+        "value",
+        [
+            "",
+            "abc",
+            "1.5",
+            "-1",
+            # A bit this LogContent does not define, e.g. from a newer runtime.
+            "4096",
+            None,
+            8,
+        ],
+    )
+    def test_unconvertible_value_is_preserved_unchanged(
+        self, log_filter: _RustLogRecordNormalizingFilter, value: Any
+    ) -> None:
+        # GIVEN
+        record = _record(openjd_log_content=value)
+
+        # WHEN
+        result = log_filter.filter(record)
+
+        # THEN
+        assert result is True
+        assert record.openjd_log_content == value  # type: ignore[attr-defined]
+        assert type(record.openjd_log_content) is type(value)  # type: ignore[attr-defined]
+
+
+class TestNormalizingFilterTimestamp:
+    def test_digit_string_becomes_int(self, log_filter: _RustLogRecordNormalizingFilter) -> None:
+        # GIVEN
+        record = _record(openjd_timestamp_usec="1762288000123456")
+
+        # WHEN
+        log_filter.filter(record)
+
+        # THEN
+        assert record.openjd_timestamp_usec == 1762288000123456  # type: ignore[attr-defined]
+        assert type(record.openjd_timestamp_usec) is int  # type: ignore[attr-defined]
+
+    @pytest.mark.parametrize("value", [123, "", "soon", "1.5", None])
+    def test_unconvertible_value_is_preserved_unchanged(
+        self, log_filter: _RustLogRecordNormalizingFilter, value: Any
+    ) -> None:
+        # GIVEN
+        record = _record(openjd_timestamp_usec=value)
+
+        # WHEN
+        log_filter.filter(record)
+
+        # THEN
+        assert record.openjd_timestamp_usec == value  # type: ignore[attr-defined]
+        assert type(record.openjd_timestamp_usec) is type(value)  # type: ignore[attr-defined]
+
+    def test_session_id_is_not_touched(self, log_filter: _RustLogRecordNormalizingFilter) -> None:
+        # GIVEN
+        record = _record(session_id="123", openjd_log_content="8")
+
+        # WHEN
+        log_filter.filter(record)
+
+        # THEN
+        assert record.session_id == "123"  # type: ignore[attr-defined]
+
+
+class TestFilterInstallation:
+    def test_importing_v1_installs_exactly_one_normalizer_on_the_logger(self) -> None:
+        # GIVEN openjd.sessions._v1 is imported (module import above)
+        installed = [
+            f
+            for f in logging.getLogger("openjd.sessions").filters
+            if isinstance(f, _RustLogRecordNormalizingFilter)
+        ]
+
+        # THEN
+        assert len(installed) == 1
+
+    def test_repeated_install_does_not_stack(self) -> None:
+        # GIVEN
+        logger = logging.getLogger(f"openjd.sessions.test.{uuid.uuid4().hex}")
+
+        # WHEN
+        _install_rust_log_record_normalizing_filter(logger)
+        _install_rust_log_record_normalizing_filter(logger)
+
+        # THEN
+        assert len(logger.filters) == 1
+        assert isinstance(logger.filters[0], _RustLogRecordNormalizingFilter)
+
+
+class TestInstalledFilterOnTheLoggerHandlePath:
+    """pyo3-log hands records to ``Logger.handle()``, which applies the logger's
+    filters before any handler. Handlers, and filters on handlers, must see the
+    normalized record."""
+
+    @pytest.fixture
+    def handler(self) -> Iterator[_CollectingHandler]:
+        handler = _CollectingHandler()
+        LOG.addHandler(handler)
+        try:
+            yield handler
+        finally:
+            LOG.removeHandler(handler)
+
+    def test_handler_sees_normalized_record(self, handler: _CollectingHandler) -> None:
+        # GIVEN
+        marker = uuid.uuid4().hex
+        record = _record(
+            msg=marker, openjd_log_content="32", openjd_timestamp_usec="7", session_id="s"
+        )
+
+        # WHEN
+        LOG.handle(record)
+
+        # THEN
+        (seen,) = [r for r in handler.records if r.getMessage() == marker]
+        assert seen.openjd_log_content is LogContent.PROCESS_CONTROL  # type: ignore[attr-defined]
+        assert seen.openjd_timestamp_usec == 7  # type: ignore[attr-defined]
+        assert seen.session_id == "s"  # type: ignore[attr-defined]
+
+    def test_handler_level_filter_sees_normalized_record(self, handler: _CollectingHandler) -> None:
+        # GIVEN
+        marker = uuid.uuid4().hex
+        seen_types: list[type] = []
+
+        class _TypeRecordingFilter(logging.Filter):
+            def filter(self, record: logging.LogRecord) -> bool:
+                if record.getMessage() == marker:
+                    seen_types.append(type(getattr(record, "openjd_log_content", None)))
+                return True
+
+        handler.addFilter(_TypeRecordingFilter())
+
+        # WHEN
+        LOG.handle(_record(msg=marker, openjd_log_content="128"))
+
+        # THEN
+        assert seen_types == [LogContent]
+
+    def test_untagged_record_still_reaches_the_handler(self, handler: _CollectingHandler) -> None:
+        # GIVEN
+        marker = uuid.uuid4().hex
+
+        # WHEN
+        LOG.handle(_record(msg=marker))
+
+        # THEN
+        assert [r.getMessage() for r in handler.records if r.getMessage() == marker] == [marker]
+
+
+class TestLogContentIsTheOnePublicClass:
+    def test_v1_log_content_is_the_public_class(self) -> None:
+        assert openjd.sessions._v1.LogContent is openjd.sessions.LogContent
+
+    def test_members_and_bit_values_are_unchanged(self) -> None:
+        assert {m.name: m.value for m in LogContent} == {
+            "BANNER": 1,
+            "FILE_PATH": 2,
+            "FILE_CONTENTS": 4,
+            "COMMAND_OUTPUT": 8,
+            "EXCEPTION_INFO": 16,
+            "PROCESS_CONTROL": 32,
+            "PARAMETER_INFO": 64,
+            "HOST_INFO": 128,
+        }