feat: add component-aware RFC 5424 application logging system
- Modify Rfc5424Formatter to read decnet_component from LogRecord
and use it as RFC 5424 APP-NAME field (falls back to 'decnet')
- Add get_logger(component) factory in decnet/logging/__init__.py
with _ComponentFilter that injects decnet_component on each record
- Wire all five layers to their component tag:
cli -> 'cli', engine -> 'engine', api -> 'api' (api.py, ingester,
routers), mutator -> 'mutator', collector -> 'collector'
- Add structured INFO/DEBUG/WARNING/ERROR log calls throughout each
layer per the defined vocabulary; DEBUG calls are suppressed unless
DECNET_DEVELOPER=true
- Add tests/test_logging.py covering factory, filter, formatter
component-awareness, fallback behaviour, and level gating
This commit is contained in:
155
tests/test_logging.py
Normal file
155
tests/test_logging.py
Normal file
@@ -0,0 +1,155 @@
|
||||
"""
|
||||
Tests for DECNET application logging system.
|
||||
|
||||
Covers:
|
||||
- get_logger() factory and _ComponentFilter injection
|
||||
- Rfc5424Formatter component-aware APP-NAME field
|
||||
- Log level gating via DECNET_DEVELOPER
|
||||
- Component tags for all five microservice layers
|
||||
"""
|
||||
|
||||
from __future__ import annotations
|
||||
|
||||
import logging
|
||||
import os
|
||||
import re
|
||||
|
||||
import pytest
|
||||
|
||||
from decnet.logging import _ComponentFilter, get_logger
|
||||
|
||||
# RFC 5424 parser: <PRI>1 TIMESTAMP HOSTNAME APP-NAME PROCID MSGID SD MSG
|
||||
_RFC5424_RE = re.compile(
|
||||
r"^<(\d+)>1 " # PRI
|
||||
r"\S+ " # TIMESTAMP
|
||||
r"\S+ " # HOSTNAME
|
||||
r"(\S+) " # APP-NAME ← what we care about
|
||||
r"\S+ " # PROCID
|
||||
r"(\S+) " # MSGID
|
||||
r"(.+)$", # SD + MSG
|
||||
)
|
||||
|
||||
|
||||
def _format_record(logger: logging.Logger, level: int, msg: str) -> str:
|
||||
"""Emit a log record through the root handler and return the formatted string."""
|
||||
from decnet.config import Rfc5424Formatter
|
||||
formatter = Rfc5424Formatter()
|
||||
record = logger.makeRecord(
|
||||
logger.name, level, "<test>", 0, msg, (), None
|
||||
)
|
||||
# Run all filters attached to the logger so decnet_component gets injected
|
||||
for f in logger.filters:
|
||||
f.filter(record)
|
||||
return formatter.format(record)
|
||||
|
||||
|
||||
class TestGetLogger:
|
||||
def test_returns_logger(self):
|
||||
log = get_logger("cli")
|
||||
assert isinstance(log, logging.Logger)
|
||||
|
||||
def test_logger_name(self):
|
||||
log = get_logger("engine")
|
||||
assert log.name == "decnet.engine"
|
||||
|
||||
def test_filter_attached(self):
|
||||
log = get_logger("api")
|
||||
assert any(isinstance(f, _ComponentFilter) for f in log.filters)
|
||||
|
||||
def test_idempotent_filter(self):
|
||||
log = get_logger("mutator")
|
||||
get_logger("mutator") # second call
|
||||
component_filters = [f for f in log.filters if isinstance(f, _ComponentFilter)]
|
||||
assert len(component_filters) == 1
|
||||
|
||||
@pytest.mark.parametrize("component", ["cli", "engine", "api", "mutator", "collector"])
|
||||
def test_all_components_registered(self, component):
|
||||
log = get_logger(component)
|
||||
assert any(isinstance(f, _ComponentFilter) for f in log.filters)
|
||||
|
||||
|
||||
class TestComponentFilter:
|
||||
def test_injects_attribute(self):
|
||||
f = _ComponentFilter("engine")
|
||||
record = logging.LogRecord("test", logging.INFO, "", 0, "msg", (), None)
|
||||
assert f.filter(record) is True
|
||||
assert record.decnet_component == "engine" # type: ignore[attr-defined]
|
||||
|
||||
def test_always_passes(self):
|
||||
f = _ComponentFilter("collector")
|
||||
record = logging.LogRecord("test", logging.DEBUG, "", 0, "msg", (), None)
|
||||
assert f.filter(record) is True
|
||||
|
||||
|
||||
class TestRfc5424FormatterComponentAware:
|
||||
@pytest.mark.parametrize("component", ["cli", "engine", "api", "mutator", "collector"])
|
||||
def test_app_name_is_component(self, component):
|
||||
log = get_logger(component)
|
||||
line = _format_record(log, logging.INFO, "test message")
|
||||
m = _RFC5424_RE.match(line)
|
||||
assert m is not None, f"Not RFC 5424: {line!r}"
|
||||
assert m.group(2) == component, f"Expected APP-NAME={component!r}, got {m.group(2)!r}"
|
||||
|
||||
def test_fallback_app_name_without_component(self):
|
||||
"""Untagged loggers (no _ComponentFilter) fall back to 'decnet'."""
|
||||
from decnet.config import Rfc5424Formatter
|
||||
formatter = Rfc5424Formatter()
|
||||
record = logging.LogRecord("some.module", logging.INFO, "", 0, "hello", (), None)
|
||||
line = formatter.format(record)
|
||||
m = _RFC5424_RE.match(line)
|
||||
assert m is not None
|
||||
assert m.group(2) == "decnet"
|
||||
|
||||
def test_msgid_is_logger_name(self):
|
||||
log = get_logger("engine")
|
||||
line = _format_record(log, logging.INFO, "deploying")
|
||||
m = _RFC5424_RE.match(line)
|
||||
assert m is not None
|
||||
assert m.group(3) == "decnet.engine"
|
||||
|
||||
|
||||
class TestLogLevelGating:
|
||||
def test_configure_logging_normal_mode_sets_info(self):
|
||||
"""_configure_logging(dev=False) must set root to INFO."""
|
||||
from decnet.config import _configure_logging, Rfc5424Formatter
|
||||
root = logging.getLogger()
|
||||
original_level = root.level
|
||||
original_handlers = root.handlers[:]
|
||||
# Remove any existing RFC5424 handlers so idempotency check doesn't skip
|
||||
root.handlers = [
|
||||
h for h in root.handlers
|
||||
if not (isinstance(h, logging.StreamHandler) and isinstance(h.formatter, Rfc5424Formatter))
|
||||
]
|
||||
try:
|
||||
_configure_logging(dev=False)
|
||||
assert root.level == logging.INFO
|
||||
finally:
|
||||
root.setLevel(original_level)
|
||||
root.handlers = original_handlers
|
||||
|
||||
def test_configure_logging_dev_mode_sets_debug(self):
|
||||
"""_configure_logging(dev=True) must set root to DEBUG."""
|
||||
from decnet.config import _configure_logging, Rfc5424Formatter
|
||||
root = logging.getLogger()
|
||||
original_level = root.level
|
||||
original_handlers = root.handlers[:]
|
||||
root.handlers = [
|
||||
h for h in root.handlers
|
||||
if not (isinstance(h, logging.StreamHandler) and isinstance(h.formatter, Rfc5424Formatter))
|
||||
]
|
||||
try:
|
||||
_configure_logging(dev=True)
|
||||
assert root.level == logging.DEBUG
|
||||
finally:
|
||||
root.setLevel(original_level)
|
||||
root.handlers = original_handlers
|
||||
|
||||
def test_debug_enabled_in_developer_mode(self, monkeypatch):
|
||||
"""Programmatically setting DEBUG on root allows debug records through."""
|
||||
root = logging.getLogger()
|
||||
original_level = root.level
|
||||
root.setLevel(logging.DEBUG)
|
||||
try:
|
||||
assert root.isEnabledFor(logging.DEBUG)
|
||||
finally:
|
||||
root.setLevel(original_level)
|
||||
Reference in New Issue
Block a user