pepperplus-cb/test/unit/logging/test_optional_field_formatter.py

import logging

import pytest

from control_backend.logging.optional_field_formatter import OptionalFieldFormatter


@pytest.fixture
def logger():
    """Create a fresh logger for each test."""
    logger = logging.getLogger(f"test_{id(object())}")
    logger.setLevel(logging.DEBUG)
    logger.handlers = []
    return logger


@pytest.fixture
def log_output(logger):
    """Capture log output and return a function to get it."""

    class ListHandler(logging.Handler):
        def __init__(self):
            super().__init__()
            self.records = []

        def emit(self, record):
            self.records.append(self.format(record))

    handler = ListHandler()
    logger.addHandler(handler)

    def get_output():
        return handler.records

    return get_output


def test_optional_field_present(logger, log_output):
    """Optional field should appear when provided in extra."""
    formatter = OptionalFieldFormatter("%(levelname)s - %(role?)s - %(message)s")
    logger.handlers[0].setFormatter(formatter)

    logger.info("test message", extra={"role": "user"})

    assert log_output() == ["INFO - user - test message"]


def test_optional_field_missing_no_default(logger, log_output):
    """Missing optional field with no default should be None."""
    formatter = OptionalFieldFormatter("%(levelname)s - %(role?)s - %(message)s")
    logger.handlers[0].setFormatter(formatter)

    logger.info("test message")

    assert log_output() == ["INFO - None - test message"]


def test_optional_field_missing_with_default(logger, log_output):
    """Missing optional field should use provided default."""
    formatter = OptionalFieldFormatter(
        "%(levelname)s - %(role?)s - %(message)s", defaults={"role": "assistant"}
    )
    logger.handlers[0].setFormatter(formatter)

    logger.info("test message")

    assert log_output() == ["INFO - assistant - test message"]


def test_optional_field_overrides_default(logger, log_output):
    """Provided extra value should override default."""
    formatter = OptionalFieldFormatter(
        "%(levelname)s - %(role?)s - %(message)s", defaults={"role": "assistant"}
    )
    logger.handlers[0].setFormatter(formatter)

    logger.info("test message", extra={"role": "user"})

    assert log_output() == ["INFO - user - test message"]


def test_multiple_optional_fields(logger, log_output):
    """Multiple optional fields should work independently."""
    formatter = OptionalFieldFormatter(
        "%(levelname)s - %(role?)s - %(request_id?)s - %(message)s", defaults={"role": "assistant"}
    )
    logger.handlers[0].setFormatter(formatter)

    logger.info("test", extra={"request_id": "123"})

    assert log_output() == ["INFO - assistant - 123 - test"]


def test_mixed_optional_and_required_fields(logger, log_output):
    """Standard fields should work alongside optional fields."""
    formatter = OptionalFieldFormatter("%(levelname)s %(name)s %(role?)s %(message)s")
    logger.handlers[0].setFormatter(formatter)

    logger.info("test", extra={"role": "user"})

    output = log_output()[0]
    assert "INFO" in output
    assert "user" in output
    assert "test" in output


def test_no_optional_fields(logger, log_output):
    """Formatter should work normally with no optional fields."""
    formatter = OptionalFieldFormatter("%(levelname)s %(message)s")
    logger.handlers[0].setFormatter(formatter)

    logger.info("test message")

    assert log_output() == ["INFO test message"]


def test_integer_format_specifier(logger, log_output):
    """Optional fields with %d specifier should work."""
    formatter = OptionalFieldFormatter(
        "%(levelname)s %(count?)d %(message)s", defaults={"count": 0}
    )
    logger.handlers[0].setFormatter(formatter)

    logger.info("test", extra={"count": 42})

    assert log_output() == ["INFO 42 test"]


def test_float_format_specifier(logger, log_output):
    """Optional fields with %f specifier should work."""
    formatter = OptionalFieldFormatter(
        "%(levelname)s %(duration?)f %(message)s", defaults={"duration": 0.0}
    )
    logger.handlers[0].setFormatter(formatter)

    logger.info("test", extra={"duration": 1.5})

    assert "1.5" in log_output()[0]


def test_empty_string_default(logger, log_output):
    """Empty string default should work."""
    formatter = OptionalFieldFormatter("%(levelname)s %(role?)s %(message)s", defaults={"role": ""})
    logger.handlers[0].setFormatter(formatter)

    logger.info("test")

    assert log_output() == ["INFO  test"]


def test_none_format_string():
    """None format string should not raise."""
    formatter = OptionalFieldFormatter(fmt=None)
    assert formatter.optional_fields == set()


def test_optional_fields_parsed_correctly():
    """Check that optional fields are correctly identified."""
    formatter = OptionalFieldFormatter("%(asctime)s %(role?)s %(level?)d %(name)s")

    assert formatter.optional_fields == {("role", "s"), ("level", "d")}


def test_format_string_normalized():
    """Check that ? is removed from format string."""
    formatter = OptionalFieldFormatter("%(role?)s %(message)s")

    assert "?" not in formatter._style._fmt
    assert "%(role)s" in formatter._style._fmt


def test_field_with_underscore(logger, log_output):
    """Field names with underscores should work."""
    formatter = OptionalFieldFormatter("%(levelname)s %(user_id?)s %(message)s")
    logger.handlers[0].setFormatter(formatter)

    logger.info("test", extra={"user_id": "abc123"})

    assert log_output() == ["INFO abc123 test"]


def test_field_with_numbers(logger, log_output):
    """Field names with numbers should work."""
    formatter = OptionalFieldFormatter("%(levelname)s %(field2?)s %(message)s")
    logger.handlers[0].setFormatter(formatter)

    logger.info("test", extra={"field2": "value"})

    assert log_output() == ["INFO value test"]


def test_multiple_log_calls(logger, log_output):
    """Formatter should work correctly across multiple log calls."""
    formatter = OptionalFieldFormatter(
        "%(levelname)s %(role?)s %(message)s", defaults={"role": "other"}
    )
    logger.handlers[0].setFormatter(formatter)

    logger.info("first", extra={"role": "assistant"})
    logger.info("second")
    logger.info("third", extra={"role": "user"})

    assert log_output() == [
        "INFO assistant first",
        "INFO other second",
        "INFO user third",
    ]


def test_default_not_mutated(logger, log_output):
    """Original defaults dict should not be mutated."""
    defaults = {"role": "other"}
    formatter = OptionalFieldFormatter("%(levelname)s %(role?)s %(message)s", defaults=defaults)
    logger.handlers[0].setFormatter(formatter)

    logger.info("test")

    assert defaults == {"role": "other"}