merge: testing → main (reconcile 2-week divergence)

tests/logging/test_file_handler.py

@@ -0,0 +1,71 @@
+"""Tests for the syslog file handler."""
+
+import logging
+import os
+from pathlib import Path
+
+import pytest
+
+import decnet.logging.file_handler as fh
+
+
+@pytest.fixture(autouse=True)
+def reset_handler(tmp_path, monkeypatch):
+    """Reset the module-level logger between tests."""
+    monkeypatch.setattr(fh, "_handler", None)
+    monkeypatch.setattr(fh, "_logger", None)
+    monkeypatch.setenv(fh._LOG_FILE_ENV, str(tmp_path / "test.log"))
+    yield
+    # Remove handlers to avoid file lock issues on next test
+    if fh._logger is not None:
+        for h in list(fh._logger.handlers):
+            h.close()
+            fh._logger.removeHandler(h)
+    fh._handler = None
+    fh._logger = None
+
+
+def test_write_creates_log_file(tmp_path):
+    log_path = tmp_path / "decnet.log"
+    os.environ[fh._LOG_FILE_ENV] = str(log_path)
+    fh.write_syslog("<134>1 2026-04-04T12:00:00+00:00 h svc - e - test message")
+    assert log_path.exists()
+    assert "test message" in log_path.read_text()
+
+
+def test_write_appends_multiple_lines(tmp_path):
+    log_path = tmp_path / "decnet.log"
+    os.environ[fh._LOG_FILE_ENV] = str(log_path)
+    for i in range(3):
+        fh.write_syslog(f"<134>1 ts host svc - event{i} -")
+    lines = log_path.read_text().splitlines()
+    assert len(lines) == 3
+    assert "event0" in lines[0]
+    assert "event2" in lines[2]
+
+
+def test_get_log_path_default(monkeypatch):
+    monkeypatch.delenv(fh._LOG_FILE_ENV, raising=False)
+    assert fh.get_log_path() == Path(fh._DEFAULT_LOG_FILE)
+
+
+def test_get_log_path_custom(monkeypatch, tmp_path):
+    custom = str(tmp_path / "custom.log")
+    monkeypatch.setenv(fh._LOG_FILE_ENV, custom)
+    assert fh.get_log_path() == Path(custom)
+
+
+def test_rotating_handler_configured(tmp_path):
+    log_path = tmp_path / "r.log"
+    os.environ[fh._LOG_FILE_ENV] = str(log_path)
+    logger = fh._get_logger()
+    handler = logger.handlers[0]
+    assert isinstance(handler, logging.handlers.RotatingFileHandler)
+    assert handler.maxBytes == fh._MAX_BYTES
+    assert handler.backupCount == fh._BACKUP_COUNT
+
+
+def test_write_syslog_does_not_raise_on_bad_path(monkeypatch):
+    monkeypatch.setenv(fh._LOG_FILE_ENV, "/no/such/dir/that/exists/decnet.log")
+    # Should not raise — falls back to StreamHandler
+    fh.write_syslog("<134>1 ts h svc - e -")

tests/logging/test_inode_aware_handler.py

@@ -0,0 +1,111 @@
+"""
+Tests for InodeAwareRotatingFileHandler.
+
+Simulates the two scenarios that break plain RotatingFileHandler:
+    1. External `rm` of the log file
+    2. External rename (logrotate-style rotation)
+
+In both cases, the next log record must end up in a recreated file on
+disk, not the orphaned inode held by the old file descriptor.
+"""
+import logging
+import os
+
+import pytest
+
+from decnet.logging.inode_aware_handler import InodeAwareRotatingFileHandler
+
+
+def _make_handler(path) -> logging.Handler:
+    h = InodeAwareRotatingFileHandler(str(path), maxBytes=10_000_000, backupCount=1)
+    h.setFormatter(logging.Formatter("%(message)s"))
+    return h
+
+
+def _record(msg: str) -> logging.LogRecord:
+    return logging.LogRecord("t", logging.INFO, __file__, 1, msg, None, None)
+
+
+def test_writes_land_in_file(tmp_path):
+    path = tmp_path / "app.log"
+    h = _make_handler(path)
+    h.emit(_record("hello"))
+    h.close()
+    assert path.read_text().strip() == "hello"
+
+
+def test_reopens_after_unlink(tmp_path):
+    path = tmp_path / "app.log"
+    h = _make_handler(path)
+    h.emit(_record("first"))
+    os.remove(path)  # simulate `rm decnet.system.log`
+    assert not path.exists()
+
+    h.emit(_record("second"))
+    h.close()
+
+    assert path.exists()
+    assert path.read_text().strip() == "second"
+
+
+def test_reopens_after_rename(tmp_path):
+    """logrotate rename-and-create: the old path is renamed, then we expect
+    writes to go to a freshly created file at the original path."""
+    path = tmp_path / "app.log"
+    h = _make_handler(path)
+    h.emit(_record("pre-rotation"))
+
+    rotated = tmp_path / "app.log.1"
+    os.rename(path, rotated)  # simulate logrotate move
+
+    h.emit(_record("post-rotation"))
+    h.close()
+
+    assert rotated.read_text().strip() == "pre-rotation"
+    assert path.read_text().strip() == "post-rotation"
+
+
+def test_no_reopen_when_file_is_stable(tmp_path, monkeypatch):
+    """Ensure we don't thrash: back-to-back emits must share one FD."""
+    path = tmp_path / "app.log"
+    h = _make_handler(path)
+    h.emit(_record("one"))
+    fd_before = h.stream.fileno()
+    h.emit(_record("two"))
+    fd_after = h.stream.fileno()
+    assert fd_before == fd_after
+    h.close()
+    assert path.read_text().splitlines() == ["one", "two"]
+
+
+def test_emit_does_not_raise_when_reopen_fails(tmp_path, monkeypatch):
+    """A failed reopen must not propagate — it would crash the caller
+    (observed in the collector worker when decnet.system.log was root-owned
+    and the collector ran non-root)."""
+    path = tmp_path / "app.log"
+    h = _make_handler(path)
+    h.emit(_record("first"))
+    os.remove(path)  # force reopen on next emit
+
+    def boom(*_a, **_kw):
+        raise PermissionError(13, "Permission denied")
+    monkeypatch.setattr(h, "_open", boom)
+
+    # Swallow the stderr traceback stdlib prints via handleError.
+    monkeypatch.setattr(h, "handleError", lambda _r: None)
+
+    # Must not raise.
+    h.emit(_record("second"))
+
+
+def test_rotation_by_size_still_works(tmp_path):
+    """maxBytes-triggered rotation must still function on top of the inode check."""
+    path = tmp_path / "app.log"
+    h = InodeAwareRotatingFileHandler(str(path), maxBytes=50, backupCount=1)
+    h.setFormatter(logging.Formatter("%(message)s"))
+    for i in range(20):
+        h.emit(_record(f"line-{i:03d}-xxxxxxxxxxxxxxx"))
+    h.close()
+
+    assert path.exists()
+    assert (tmp_path / "app.log.1").exists()

tests/logging/test_log_file_mount.py

@@ -0,0 +1,73 @@
+"""Tests for compose generation — logging block and absence of volume mounts."""
+
+from decnet.composer import generate_compose, _DOCKER_LOGGING
+from decnet.config import DeckyConfig, DecnetConfig
+from decnet.distros import DISTROS
+
+
+def _make_config(log_file: str | None = None) -> DecnetConfig:
+    profile = DISTROS["debian"]
+    decky = DeckyConfig(
+        name="decky-01",
+        ip="10.0.0.10",
+        services=["http"],
+        distro="debian",
+        base_image=profile.image,
+        build_base=profile.build_base,
+        hostname="test-host",
+    )
+    return DecnetConfig(
+        mode="unihost",
+        interface="eth0",
+        subnet="10.0.0.0/24",
+        gateway="10.0.0.1",
+        deckies=[decky],
+        log_file=log_file,
+    )
+
+
+class TestComposeLogging:
+    def test_service_container_has_logging_block(self):
+        config = _make_config()
+        compose = generate_compose(config)
+        fragment = compose["services"]["decky-01-http"]
+        assert "logging" in fragment
+        assert fragment["logging"] == _DOCKER_LOGGING
+
+    def test_logging_driver_is_json_file(self):
+        config = _make_config()
+        compose = generate_compose(config)
+        fragment = compose["services"]["decky-01-http"]
+        assert fragment["logging"]["driver"] == "json-file"
+
+    def test_logging_has_rotation_options(self):
+        config = _make_config()
+        compose = generate_compose(config)
+        fragment = compose["services"]["decky-01-http"]
+        opts = fragment["logging"]["options"]
+        assert "max-size" in opts
+        assert "max-file" in opts
+
+    def test_base_container_has_no_logging_block(self):
+        """Base containers run sleep infinity and produce no app logs."""
+        config = _make_config()
+        compose = generate_compose(config)
+        base = compose["services"]["decky-01"]
+        assert "logging" not in base
+
+    def test_no_volume_mounts_on_service_container(self):
+        config = _make_config(log_file="/tmp/decnet.log")
+        compose = generate_compose(config)
+        fragment = compose["services"]["decky-01-http"]
+        assert not fragment.get("volumes")
+
+    def test_no_decnet_log_file_env_var(self):
+        config = _make_config(log_file="/tmp/decnet.log")
+        compose = generate_compose(config)
+        fragment = compose["services"]["decky-01-http"]
+        assert "DECNET_LOG_FILE" not in fragment.get("environment", {})
+
+    def test_no_log_network_in_networks(self):
+        config = _make_config()
+        compose = generate_compose(config)
+        assert "decnet_logs" not in compose["networks"]

tests/logging/test_logging.py

@@ -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)

tests/logging/test_logging_forwarder.py

@@ -0,0 +1,61 @@
+"""
+Tests for decnet.logging.forwarder — parse_log_target, probe_log_target.
+"""
+from unittest.mock import MagicMock, patch
+
+import pytest
+
+from decnet.logging.forwarder import parse_log_target, probe_log_target
+
+
+class TestParseLogTarget:
+    def test_valid_ip_port(self):
+        host, port = parse_log_target("192.168.1.5:5140")
+        assert host == "192.168.1.5"
+        assert port == 5140
+
+    def test_valid_hostname_port(self):
+        host, port = parse_log_target("logstash.internal:9600")
+        assert host == "logstash.internal"
+        assert port == 9600
+
+    def test_no_colon_raises(self):
+        with pytest.raises(ValueError, match="Invalid log_target"):
+            parse_log_target("192.168.1.5")
+
+    def test_non_digit_port_raises(self):
+        with pytest.raises(ValueError, match="Invalid log_target"):
+            parse_log_target("192.168.1.5:syslog")
+
+    def test_empty_string_raises(self):
+        with pytest.raises(ValueError):
+            parse_log_target("")
+
+    def test_multiple_colons_uses_last_as_port(self):
+        # IPv6-style or hostname with colons — rsplit takes the last segment
+        host, port = parse_log_target("::1:514")
+        assert port == 514
+
+
+class TestProbeLogTarget:
+    def test_returns_true_when_reachable(self):
+        mock_conn = MagicMock()
+        mock_conn.__enter__ = MagicMock(return_value=mock_conn)
+        mock_conn.__exit__ = MagicMock(return_value=False)
+        with patch("decnet.logging.forwarder.socket.create_connection",
+                   return_value=mock_conn):
+            assert probe_log_target("192.168.1.5:5140") is True
+
+    def test_returns_false_when_connection_refused(self):
+        with patch("decnet.logging.forwarder.socket.create_connection",
+                   side_effect=OSError("Connection refused")):
+            assert probe_log_target("192.168.1.5:5140") is False
+
+    def test_returns_false_on_timeout(self):
+        with patch("decnet.logging.forwarder.socket.create_connection",
+                   side_effect=TimeoutError("timed out")):
+            assert probe_log_target("192.168.1.5:5140") is False
+
+    def test_returns_false_on_invalid_target(self):
+        # ValueError from parse_log_target is caught and returns False
+        assert probe_log_target("not-a-valid-target") is False

tests/logging/test_syslog_formatter.py

@@ -0,0 +1,134 @@
+"""Tests for RFC 5424 syslog formatter."""
+
+import re
+from datetime import datetime, timezone
+
+
+from decnet.logging.syslog_formatter import (
+    SEVERITY_ERROR,
+    SEVERITY_INFO,
+    SEVERITY_WARNING,
+    format_rfc5424,
+)
+
+# RFC 5424 header regex: <PRI>1 TIMESTAMP HOSTNAME APP-NAME PROCID MSGID SD [MSG]
+_RFC5424_RE = re.compile(
+    r"^<(\d+)>1 "                       # PRI + version
+    r"(\S+) "                            # TIMESTAMP
+    r"(\S+) "                            # HOSTNAME
+    r"(\S+) "                            # APP-NAME
+    r"- "                                # PROCID (NILVALUE)
+    r"(\S+) "                            # MSGID
+    r"(.+)$",                            # SD + optional MSG
+)
+
+
+def _parse(line: str) -> re.Match:
+    m = _RFC5424_RE.match(line)
+    assert m is not None, f"Not RFC 5424: {line!r}"
+    return m
+
+
+class TestPRI:
+    def test_info_pri(self):
+        line = format_rfc5424("http", "host1", "request", SEVERITY_INFO)
+        m = _parse(line)
+        pri = int(m.group(1))
+        assert pri == 16 * 8 + 6  # local0 + info = 134
+
+    def test_warning_pri(self):
+        line = format_rfc5424("http", "host1", "warn", SEVERITY_WARNING)
+        pri = int(_parse(line).group(1))
+        assert pri == 16 * 8 + 4  # 132
+
+    def test_error_pri(self):
+        line = format_rfc5424("http", "host1", "err", SEVERITY_ERROR)
+        pri = int(_parse(line).group(1))
+        assert pri == 16 * 8 + 3  # 131
+
+    def test_pri_range(self):
+        for sev in range(8):
+            line = format_rfc5424("svc", "h", "e", sev)
+            pri = int(_parse(line).group(1))
+            assert 0 <= pri <= 191
+
+
+class TestTimestamp:
+    def test_utc_timestamp(self):
+        ts_str = datetime(2026, 4, 4, 12, 0, 0, tzinfo=timezone.utc).isoformat()
+        line = format_rfc5424("svc", "h", "e", timestamp=datetime(2026, 4, 4, 12, 0, 0, tzinfo=timezone.utc))
+        m = _parse(line)
+        assert m.group(2) == ts_str
+
+    def test_default_timestamp_is_utc(self):
+        line = format_rfc5424("svc", "h", "e")
+        ts_field = _parse(line).group(2)
+        # Should end with +00:00 or Z
+        assert "+" in ts_field or ts_field.endswith("Z")
+
+
+class TestHeader:
+    def test_hostname(self):
+        line = format_rfc5424("http", "decky-01", "request")
+        assert _parse(line).group(3) == "decky-01"
+
+    def test_appname(self):
+        line = format_rfc5424("mysql", "host", "login_attempt")
+        assert _parse(line).group(4) == "mysql"
+
+    def test_msgid(self):
+        line = format_rfc5424("ftp", "host", "login_attempt")
+        assert _parse(line).group(5) == "login_attempt"
+
+    def test_procid_is_nilvalue(self):
+        line = format_rfc5424("svc", "h", "e")
+        assert " - " in line  # PROCID is always NILVALUE
+
+    def test_appname_truncated(self):
+        long_name = "a" * 100
+        line = format_rfc5424(long_name, "h", "e")
+        appname = _parse(line).group(4)
+        assert len(appname) <= 48
+
+    def test_msgid_truncated(self):
+        long_msgid = "x" * 100
+        line = format_rfc5424("svc", "h", long_msgid)
+        msgid = _parse(line).group(5)
+        assert len(msgid) <= 32
+
+
+class TestStructuredData:
+    def test_nilvalue_when_no_fields(self):
+        line = format_rfc5424("svc", "h", "e")
+        sd_and_msg = _parse(line).group(6)
+        assert sd_and_msg.startswith("-")
+
+    def test_sd_element_present(self):
+        line = format_rfc5424("http", "h", "request", remote_addr="1.2.3.4", method="GET")
+        sd_and_msg = _parse(line).group(6)
+        assert sd_and_msg.startswith("[relay@55555 ")
+        assert 'remote_addr="1.2.3.4"' in sd_and_msg
+        assert 'method="GET"' in sd_and_msg
+
+    def test_sd_escape_double_quote(self):
+        line = format_rfc5424("svc", "h", "e", ua='foo"bar')
+        assert r'ua="foo\"bar"' in line
+
+    def test_sd_escape_backslash(self):
+        line = format_rfc5424("svc", "h", "e", path="a\\b")
+        assert r'path="a\\b"' in line
+
+    def test_sd_escape_close_bracket(self):
+        line = format_rfc5424("svc", "h", "e", val="a]b")
+        assert r'val="a\]b"' in line
+
+
+class TestMsg:
+    def test_optional_msg_appended(self):
+        line = format_rfc5424("svc", "h", "e", msg="hello world")
+        assert line.endswith(" hello world")
+
+    def test_no_msg_no_trailing_space_in_sd(self):
+        line = format_rfc5424("svc", "h", "e", key="val")
+        # SD element closes with ]
+        assert line.rstrip().endswith("]")