feat(compiler): add centralized structured logging (#6) (#50)

Implement structured, machine-readable logging per MASTER_SPEC §22, §25.7 in
compiler/common/log.py.

- DebugLevel IntEnum with the four levels (None/Basic/Verbose/Developer),
  ordered; DebugLevel.from_config maps a debug config section to a threshold
  (disabled -> None).
- LogRecord: immutable structured record (level, event, fields) with a
  machine-readable to_json; no timestamps, so logging stays deterministic.
- StructuredLogger: filters by threshold, emits to an injectable sink, and
  offers basic/verbose/developer helpers plus from_config. No global state.
- json_lines_sink writes one JSON object per line to a stream (never print).
- Tighten configuration.schema.json debug.level to enum
  none/basic/verbose/developer.

Tests: level filtering across all four levels, structured/immutable records,
config integration, and a guard asserting no print() exists in the compiler
package.

Co-authored-by: kunail0804 <kunail0804@gmail.com>
Co-authored-by: Claude Opus 4.8 <noreply@anthropic.com>

compiler/common/log.py

@@ -0,0 +1,125 @@
+"""Centralized structured logging for the compiler (MASTER_SPEC §22, §25.7).
+
+Logs are structured :class:`LogRecord` objects — never free-form strings — so
+they can be consumed programmatically without parsing. Emission is filtered by a
+:class:`DebugLevel` threshold driven by configuration (``config.debug``), and the
+compiler never calls ``print``.
+
+Records carry no timestamp so that logging stays deterministic and testable. The
+output destination is an injectable ``sink`` callable; the ComfyUI nodes (or a
+test) supply one. :func:`json_lines_sink` provides a ready-made sink that writes
+one JSON object per line to a stream.
+"""
+
+from __future__ import annotations
+
+import json
+import sys
+from collections.abc import Callable, Mapping
+from dataclasses import dataclass, field
+from enum import IntEnum
+from types import MappingProxyType
+from typing import IO, Any
+
+_EMPTY_FIELDS: Mapping[str, Any] = MappingProxyType({})
+
+
+class DebugLevel(IntEnum):
+    """Debug verbosity levels (§22.1), ordered from least to most verbose."""
+
+    NONE = 0
+    BASIC = 1
+    VERBOSE = 2
+    DEVELOPER = 3
+
+    @classmethod
+    def from_config(cls, *, enabled: bool, level: str) -> DebugLevel:
+        """Resolve the active level from a ``debug`` config section.
+
+        When debugging is disabled the level is always :attr:`NONE`, regardless
+        of the configured ``level``.
+
+        Raises:
+            ValueError: If ``level`` is not a known level name.
+        """
+        if not enabled:
+            return cls.NONE
+        try:
+            return cls[level.upper()]
+        except KeyError:
+            raise ValueError(f"Unknown debug level '{level}'.") from None
+
+
+@dataclass(frozen=True)
+class LogRecord:
+    """A single structured log record."""
+
+    level: DebugLevel
+    event: str
+    fields: Mapping[str, Any] = field(default_factory=lambda: _EMPTY_FIELDS)
+
+    def __post_init__(self) -> None:
+        if not isinstance(self.fields, MappingProxyType):
+            frozen = MappingProxyType(dict(self.fields)) if self.fields else _EMPTY_FIELDS
+            object.__setattr__(self, "fields", frozen)
+
+    def to_json(self) -> dict[str, Any]:
+        return {
+            "level": self.level.name.lower(),
+            "event": self.event,
+            "fields": dict(self.fields),
+        }
+
+
+class StructuredLogger:
+    """Emits structured log records filtered by a configured :class:`DebugLevel`.
+
+    A record is emitted only when its level is not :attr:`DebugLevel.NONE` and is
+    at or below the logger's threshold. Emission goes to the injected ``sink``;
+    without a sink the logger is silent but still returns the (unemitted) record.
+    """
+
+    def __init__(
+        self,
+        level: DebugLevel = DebugLevel.NONE,
+        sink: Callable[[LogRecord], None] | None = None,
+    ) -> None:
+        self.level = level
+        self._sink = sink
+
+    @classmethod
+    def from_config(cls, config: Any, sink: Callable[[LogRecord], None] | None = None):
+        """Build a logger from a Config's ``debug`` section."""
+        level = DebugLevel.from_config(enabled=config.debug.enabled, level=config.debug.level)
+        return cls(level=level, sink=sink)
+
+    def log(self, level: DebugLevel, event: str, **fields: Any) -> LogRecord | None:
+        """Emit a record at ``level``; return it, or None if filtered out."""
+        if level == DebugLevel.NONE or level > self.level:
+            return None
+        record = LogRecord(level=level, event=event, fields=fields)
+        if self._sink is not None:
+            self._sink(record)
+        return record
+
+    def basic(self, event: str, **fields: Any) -> LogRecord | None:
+        return self.log(DebugLevel.BASIC, event, **fields)
+
+    def verbose(self, event: str, **fields: Any) -> LogRecord | None:
+        return self.log(DebugLevel.VERBOSE, event, **fields)
+
+    def developer(self, event: str, **fields: Any) -> LogRecord | None:
+        return self.log(DebugLevel.DEVELOPER, event, **fields)
+
+
+def json_lines_sink(stream: IO[str] | None = None) -> Callable[[LogRecord], None]:
+    """Return a sink that writes each record as one JSON line to ``stream``.
+
+    Defaults to ``sys.stderr``. Uses ``json.dumps`` (never ``print``).
+    """
+    target = stream if stream is not None else sys.stderr
+
+    def _sink(record: LogRecord) -> None:
+        target.write(json.dumps(record.to_json(), sort_keys=True) + "\n")
+
+    return _sink

schemas/json/configuration.schema.json

@@ -52,7 +52,7 @@
       "additionalProperties": false,
       "properties": {
         "enabled": { "type": "boolean" },
-        "level": { "type": "string" }
+        "level": { "type": "string", "enum": ["none", "basic", "verbose", "developer"] }
       }
     }
   }

tests/test_logging.py

@@ -0,0 +1,133 @@
+"""Tests for the structured logger (issue #6, MASTER_SPEC §22, §25.7)."""
+
+from __future__ import annotations
+
+import dataclasses
+from pathlib import Path
+
+import pytest
+
+from compiler.common.config import Config
+from compiler.common.log import DebugLevel, LogRecord, StructuredLogger
+
+# --- DebugLevel ------------------------------------------------------------
+
+
+def test_four_debug_levels_ordered() -> None:
+    assert DebugLevel.NONE < DebugLevel.BASIC < DebugLevel.VERBOSE < DebugLevel.DEVELOPER
+
+
+def test_debug_level_from_config_disabled_is_none() -> None:
+    assert DebugLevel.from_config(enabled=False, level="basic") is DebugLevel.NONE
+
+
+@pytest.mark.parametrize(
+    ("level", "expected"),
+    [
+        ("basic", DebugLevel.BASIC),
+        ("verbose", DebugLevel.VERBOSE),
+        ("developer", DebugLevel.DEVELOPER),
+        ("none", DebugLevel.NONE),
+    ],
+)
+def test_debug_level_from_config_enabled(level: str, expected: DebugLevel) -> None:
+    assert DebugLevel.from_config(enabled=True, level=level) is expected
+
+
+def test_unknown_level_raises() -> None:
+    with pytest.raises(ValueError):
+        DebugLevel.from_config(enabled=True, level="bogus")
+
+
+# --- filtering -------------------------------------------------------------
+
+
+def make_logger(level: DebugLevel) -> tuple[StructuredLogger, list[LogRecord]]:
+    sink: list[LogRecord] = []
+    return StructuredLogger(level=level, sink=sink.append), sink
+
+
+def test_basic_logger_emits_basic_only() -> None:
+    logger, sink = make_logger(DebugLevel.BASIC)
+    assert logger.basic("stage_started", stage="resolver") is not None
+    assert logger.verbose("detail") is None
+    assert logger.developer("trace") is None
+    assert [r.event for r in sink] == ["stage_started"]
+
+
+def test_developer_logger_emits_all() -> None:
+    logger, sink = make_logger(DebugLevel.DEVELOPER)
+    logger.basic("a")
+    logger.verbose("b")
+    logger.developer("c")
+    assert [r.event for r in sink] == ["a", "b", "c"]
+
+
+def test_none_logger_emits_nothing() -> None:
+    logger, sink = make_logger(DebugLevel.NONE)
+    logger.basic("a")
+    logger.verbose("b")
+    logger.developer("c")
+    assert sink == []
+
+
+def test_verbose_logger_emits_basic_and_verbose() -> None:
+    logger, sink = make_logger(DebugLevel.VERBOSE)
+    logger.basic("a")
+    logger.verbose("b")
+    logger.developer("c")
+    assert [r.event for r in sink] == ["a", "b"]
+
+
+# --- structured records ----------------------------------------------------
+
+
+def test_record_is_structured_not_a_string() -> None:
+    logger, sink = make_logger(DebugLevel.BASIC)
+    logger.basic("stage_started", stage="resolver", count=3)
+    record = sink[0]
+    assert record.event == "stage_started"
+    assert record.fields == {"stage": "resolver", "count": 3}
+    assert record.level is DebugLevel.BASIC
+
+
+def test_record_to_json_machine_readable() -> None:
+    record = LogRecord(level=DebugLevel.VERBOSE, event="e", fields={"k": "v"})
+    assert record.to_json() == {"level": "verbose", "event": "e", "fields": {"k": "v"}}
+
+
+def test_record_is_immutable() -> None:
+    record = LogRecord(level=DebugLevel.BASIC, event="e", fields={})
+    with pytest.raises(dataclasses.FrozenInstanceError):
+        record.event = "x"  # type: ignore[misc]
+
+
+# --- config integration ----------------------------------------------------
+
+
+def test_from_config_uses_debug_section() -> None:
+    config = Config.from_json({"debug": {"enabled": True, "level": "verbose"}})
+    logger, sink = make_logger(DebugLevel.NONE)
+    logger = StructuredLogger.from_config(config, sink=sink.append)
+    assert logger.level is DebugLevel.VERBOSE
+    logger.verbose("ok")
+    assert [r.event for r in sink] == ["ok"]
+
+
+def test_default_logger_is_silent_and_needs_no_sink() -> None:
+    # A logger without a sink must not raise when emitting.
+    logger = StructuredLogger(level=DebugLevel.DEVELOPER)
+    assert logger.basic("a") is not None  # returns record, emits nowhere
+
+
+# --- no print() in the compiler --------------------------------------------
+
+
+def test_no_print_in_compiler_package() -> None:
+    compiler_dir = Path(__file__).resolve().parent.parent / "compiler"
+    offenders = [
+        py.relative_to(compiler_dir).as_posix()
+        for py in compiler_dir.rglob("*.py")
+        if "print(" in py.read_text(encoding="utf-8")
+    ]
+    assert offenders == [], f"print() found in compiler package: {offenders}"