diff --git a/docs/developers-guide.md b/docs/developers-guide.md index 81317eb9..c428ddaa 100644 --- a/docs/developers-guide.md +++ b/docs/developers-guide.md @@ -780,6 +780,11 @@ the importer, imported module, and dependency direction. The enforced groups are: +- `logging_port`: the public `episodic.logging` seam used by every package. +- `logging_backend`: the `femtologging` implementation, which only + `logging_port` may import. +- `external_libraries`: approved third-party libraries, tracked as import + edges alongside the internal groups. - `domain_ports`: canonical domain types, canonical ports, ingestion ports, canonical constraint names, and LLM ports. - `application`: canonical services, profile/template workflows, @@ -791,10 +796,13 @@ The enforced groups are: - `composition_root`: modules that wire concrete adapters, currently `episodic.api.runtime` and `episodic.worker.runtime`. -When adding a new port or adapter, update `[tool.hecate]` in `pyproject.toml` -in the same change as the package. Keep composition-root prefixes before -broader adapter prefixes because Hecate uses first-match group ordering. Add or -adjust fixture coverage in `tests/fixtures/architecture/` and run: +`include_external_packages = true` makes Hecate classify third-party import +edges. The groups are ordered by first matching prefix: keep `logging_port` +and `logging_backend` before the broad `external_libraries` group so the latter +cannot silently permit direct femtologging imports. When adding a new port or +adapter, update `[tool.hecate]` in `pyproject.toml` in the same change as the +package. Add or adjust fixture coverage in `tests/fixtures/architecture/` and +run: ```shell uv run pytest -q tests/test_architecture_enforcement.py \ @@ -1926,17 +1934,27 @@ normalizer. ## Logging -Structured logging uses femtologging v0.1.0-style logger methods. Import -`get_logger` (or `getLogger` when matching stdlib naming) from -`episodic.logging`, then emit via `logger.info(...)`, `logger.warning(...)`, -`logger.error(...)`, or `logger.exception(...)`. - -Keep `episodic.logging.configure_logging(...)` as the local configuration seam. -The legacy `log_info`, `log_warning`, and `log_error` helpers remain available -for compatibility, but new code should prefer calling the logger methods -directly. Femtologging still expects pre-formatted messages rather than stdlib -`logger.info("%s", value)` lazy formatting, so build the final string before -calling the method. +`episodic.logging` is the project's logging port. Call sites obtain a +`LoggerHandle` through `get_logger` (or the stdlib-compatible `getLogger` alias) +and emit through `log_debug`, `log_info`, `log_warning`, `log_error`, or +`log_exception`. Pass percent-style templates and arguments to the port; it +eagerly formats the final message for femtologging. + +The handle deliberately exposes no level methods. The raw femtologging logger +is an implementation detail, not a public surface: logging behaviour that +crosses package boundaries must pass through the port. This gives each call +site a stable emission contract while allowing the port to attach the request +correlation identifier and future common fields consistently. + +Keep `configure_logging(...)` as the local configuration seam. `log_exception` +records exception information by default; the other wrappers accept optional +`exc_info` explicitly when a caller needs it. + +The import boundary is enforced by Hecate's `logging_port` and +`logging_backend` groups. The direct-call boundary has two independent gates: +the opaque `LoggerHandle` is rejected by `ty` when code accesses `.info` or +another level method, and `tests/test_logging_port_enforcement.py` scans the +production tree so a regression reports every offending file. ### LogLevel diff --git a/episodic/api/authorization.py b/episodic/api/authorization.py index ecff80c7..620e7a02 100644 --- a/episodic/api/authorization.py +++ b/episodic/api/authorization.py @@ -7,7 +7,7 @@ import falcon -from episodic.logging import LogLevel, get_logger, log_warning +from episodic.logging import get_logger, log_debug, log_warning logger = get_logger(__name__) @@ -173,7 +173,10 @@ def _log_authorization_denial( context: AuthorizationContext, ) -> None: """Log non-permit decisions without recording credential material.""" - logger.log( - LogLevel.DEBUG, - (f"Authorization denied with {decision} for {context.method} {context.path}."), + log_debug( + logger, + "Authorization denied with %s for %s %s.", + decision, + context.method, + context.path, ) diff --git a/episodic/canonical/ingestion_service.py b/episodic/canonical/ingestion_service.py index a957f031..b24d3573 100644 --- a/episodic/canonical/ingestion_service.py +++ b/episodic/canonical/ingestion_service.py @@ -21,7 +21,7 @@ import typing as typ from episodic.asyncio_tasks import TaskMetadata, create_task -from episodic.logging import get_logger +from episodic.logging import get_logger, log_info from .domain import IngestionRequest from .services import ingest_sources @@ -185,10 +185,14 @@ def _log_multi_source_outcome( episode: CanonicalEpisode, ) -> None: """Log the completed multi-source ingestion outcome.""" - logger.info( - f"Multi-source ingestion complete: {len(source_inputs)} sources, " - f"{len(outcome.preferred_sources)} preferred, " - f"{len(outcome.rejected_sources)} rejected. Episode {episode.id}." + log_info( + logger, + "Multi-source ingestion complete: %s sources, %s preferred, %s rejected. " + "Episode %s.", + len(source_inputs), + len(outcome.preferred_sources), + len(outcome.rejected_sources), + episode.id, ) diff --git a/episodic/canonical/services.py b/episodic/canonical/services.py index 74a86892..2539d00c 100644 --- a/episodic/canonical/services.py +++ b/episodic/canonical/services.py @@ -20,7 +20,7 @@ import typing as typ import uuid -from episodic.logging import get_logger +from episodic.logging import get_logger, log_info from . import reference_documents from .domain import ( @@ -268,8 +268,11 @@ async def ingest_sources( await uow.approval_events.add(event) await uow.commit() - logger.info( - f"Ingested {len(request.sources)} sources into canonical episode {episode_id}." + log_info( + logger, + "Ingested %s sources into canonical episode %s.", + len(request.sources), + episode_id, ) return episode diff --git a/episodic/canonical/storage/migration_check.py b/episodic/canonical/storage/migration_check.py index 00fffc00..943f58f9 100644 --- a/episodic/canonical/storage/migration_check.py +++ b/episodic/canonical/storage/migration_check.py @@ -24,7 +24,7 @@ from episodic.canonical.storage.alembic_helpers import apply_migrations from episodic.canonical.storage.models import Base -from episodic.logging import get_logger +from episodic.logging import get_logger, log_error, log_exception, log_info if typ.TYPE_CHECKING: import sqlalchemy as sa @@ -75,7 +75,9 @@ async def check_migrations_cli() -> int: detected, 2 on infrastructure errors. """ if importlib.util.find_spec("py_pglite") is None: - _logger.error("py-pglite is not installed; cannot run migration drift check.") + log_error( + _logger, "py-pglite is not installed; cannot run migration drift check." + ) return 2 import tempfile @@ -95,24 +97,24 @@ async def check_migrations_cli() -> int: dsn = config.get_connection_string() engine = create_async_engine(dsn, pool_pre_ping=True) try: - _logger.info("Applying migrations to ephemeral database.") + log_info(_logger, "Applying migrations to ephemeral database.") await apply_migrations(engine) - _logger.info("Checking for schema drift.") + log_info(_logger, "Checking for schema drift.") diffs = await detect_schema_drift(engine) finally: await engine.dispose() except _INFRASTRUCTURE_ERRORS: - _logger.exception("Infrastructure error.") + log_exception(_logger, "Infrastructure error.") return 2 if diffs: - _logger.error(f"Schema drift detected ({len(diffs)} difference(s)):") + log_error(_logger, "Schema drift detected (%s difference(s)):", len(diffs)) for diff in diffs: - _logger.error(f" {diff}") + log_error(_logger, " %s", diff) return 1 - _logger.info("No schema drift detected.") + log_info(_logger, "No schema drift detected.") return 0 diff --git a/episodic/canonical/storage/uow.py b/episodic/canonical/storage/uow.py index e49821a3..6ce90052 100644 --- a/episodic/canonical/storage/uow.py +++ b/episodic/canonical/storage/uow.py @@ -16,7 +16,7 @@ from episodic.canonical.unit_of_work_protocols import CanonicalUnitOfWork from episodic.cost.storage import SqlAlchemyCostLedgerStore -from episodic.logging import get_logger +from episodic.logging import get_logger, log_info from .episode_repository import SqlAlchemyEpisodeRepository from .generation_runs import SqlAlchemyGenerationRunStore @@ -211,7 +211,7 @@ async def commit(self) -> None: If no unit-of-work session is active. """ # noqa: DOC502 # Documents an exception propagated by the helper. await self._apply_session_action("commit") - logger.info("Committed canonical unit of work.") + log_info(logger, "Committed canonical unit of work.") async def flush(self) -> None: """Flush pending unit-of-work changes.""" diff --git a/episodic/concurrent_interpreters.py b/episodic/concurrent_interpreters.py index 1d341a09..ebfe4f64 100644 --- a/episodic/concurrent_interpreters.py +++ b/episodic/concurrent_interpreters.py @@ -9,12 +9,13 @@ import collections.abc as cabc import concurrent.futures as cf import dataclasses as dc -import logging +import json import os import threading import time import typing as typ +from episodic.logging import get_logger, log_exception, log_info from episodic.metrics_ports import ( BoundedValueMetricsPort, NoopBoundedValueMetrics, @@ -32,7 +33,7 @@ _METRIC_MAP_ITEMS = "interpreter_pool.map.items" _METRIC_SHUTDOWN_LATENCY_MS = "interpreter_pool.shutdown.latency_ms" _TRUTHY_VALUES = frozenset({"1", "on", "true", "yes"}) -_log = logging.getLogger(__name__) +_log = get_logger(__name__) class CpuTaskExecutorMetricsPort(BoundedValueMetricsPort, typ.Protocol): @@ -189,9 +190,16 @@ def _get_executor(self) -> cf.Executor: ) except Exception: outcome = "error" - _log.exception( - "Failed to create interpreter-pool executor", - extra={"max_workers": self._max_workers}, + log_exception( + _log, + "%s", + json.dumps( + { + "event": "interpreter_pool_executor_creation_failed", + "max_workers": self._max_workers, + }, + sort_keys=True, + ), ) raise finally: @@ -199,9 +207,16 @@ def _get_executor(self) -> cf.Executor: _METRIC_POOL_CREATIONS, labels={"outcome": outcome}, ) - _log.info( - "Created interpreter-pool executor", - extra={"max_workers": self._max_workers}, + log_info( + _log, + "%s", + json.dumps( + { + "event": "interpreter_pool_executor_created", + "max_workers": self._max_workers, + }, + sort_keys=True, + ), ) return self._executor @@ -218,9 +233,16 @@ def shutdown(self) -> None: executor.shutdown(wait=True) except Exception: outcome = "error" - _log.exception( - "Interpreter-pool executor shutdown failed", - extra={"max_workers": self._max_workers}, + log_exception( + _log, + "%s", + json.dumps( + { + "event": "interpreter_pool_executor_shutdown_failed", + "max_workers": self._max_workers, + }, + sort_keys=True, + ), ) raise finally: @@ -229,9 +251,16 @@ def shutdown(self) -> None: (self._clock.monotonic_seconds() - started) * 1000, labels={"outcome": outcome}, ) - _log.info( - "Shut down interpreter-pool executor", - extra={"max_workers": self._max_workers}, + log_info( + _log, + "%s", + json.dumps( + { + "event": "interpreter_pool_executor_shutdown", + "max_workers": self._max_workers, + }, + sort_keys=True, + ), ) @typ.override @@ -258,12 +287,17 @@ def map_ordered_sync() -> list[_OutputT]: _METRIC_MAP_CALLS, labels={"outcome": "error"}, ) - _log.exception( - "Interpreter-pool executor map failed", - extra={ - "item_count": len(items), - "max_workers": self._max_workers, - }, + log_exception( + _log, + "%s", + json.dumps( + { + "event": "interpreter_pool_executor_map_failed", + "item_count": len(items), + "max_workers": self._max_workers, + }, + sort_keys=True, + ), ) raise self._metrics.increment_counter( @@ -292,9 +326,17 @@ def _build_cpu_task_executor_from_environment( _METRIC_EXECUTOR_SELECTIONS, labels={"executor": "inline", "reason": "feature_flag_disabled"}, ) - _log.info( - "Using inline CPU task executor", - extra={"reason": "feature_flag_disabled"}, + log_info( + _log, + "%s", + json.dumps( + { + "event": "cpu_task_executor_selected", + "executor": "inline", + "reason": "feature_flag_disabled", + }, + sort_keys=True, + ), ) return InlineCpuTaskExecutor() if not _capability_check(): @@ -302,9 +344,17 @@ def _build_cpu_task_executor_from_environment( _METRIC_EXECUTOR_SELECTIONS, labels={"executor": "inline", "reason": "interpreter_pool_unavailable"}, ) - _log.info( - "Using inline CPU task executor", - extra={"reason": "interpreter_pool_unavailable"}, + log_info( + _log, + "%s", + json.dumps( + { + "event": "cpu_task_executor_selected", + "executor": "inline", + "reason": "interpreter_pool_unavailable", + }, + sort_keys=True, + ), ) return InlineCpuTaskExecutor() max_workers = _parse_optional_positive_int( @@ -314,9 +364,17 @@ def _build_cpu_task_executor_from_environment( _METRIC_EXECUTOR_SELECTIONS, labels={"executor": "interpreter_pool", "reason": "enabled"}, ) - _log.info( - "Using interpreter-pool CPU task executor", - extra={"max_workers": max_workers}, + log_info( + _log, + "%s", + json.dumps( + { + "event": "cpu_task_executor_selected", + "executor": "interpreter_pool", + "max_workers": max_workers, + }, + sort_keys=True, + ), ) return InterpreterPoolCpuTaskExecutor(max_workers=max_workers, metrics=metrics) diff --git a/episodic/generation/chapter_marker_generator.py b/episodic/generation/chapter_marker_generator.py index b7d2bdbf..44038ceb 100644 --- a/episodic/generation/chapter_marker_generator.py +++ b/episodic/generation/chapter_marker_generator.py @@ -16,7 +16,7 @@ _validate_chapters_align_to_segments, ) from episodic.llm import LLMPort, LLMRequest, LLMResponse -from episodic.logging import log_info +from episodic.logging import log_info, log_warning @dc.dataclass(frozen=True, slots=True) @@ -45,7 +45,7 @@ def _result_from_response(response: LLMResponse) -> ChapterMarkersResult: payload = json.loads(response.text) except json.JSONDecodeError as exc: msg = "LLM response is not valid JSON." - logger.warning("chapter_markers_response_invalid_json") + log_warning(logger, "chapter_markers_response_invalid_json") raise ChapterMarkersResponseFormatError(msg) from exc payload_dict = _decode_object(payload, "response") @@ -63,7 +63,7 @@ def _result_from_response(response: LLMResponse) -> ChapterMarkersResult: finish_reason=response.finish_reason, ) except ValueError as exc: - logger.warning("chapter_markers_response_invalid_timing") + log_warning(logger, "chapter_markers_response_invalid_timing") raise ChapterMarkersResponseFormatError(str(exc)) from exc log_info( logger, @@ -90,12 +90,12 @@ async def generate( provider_operation=self.config.provider_operation, token_budget=self.config.token_budget, ) - logger.info("chapter_markers_generation_requested") + log_info(logger, "chapter_markers_generation_requested") response = await self.llm.generate(request) result = self._result_from_response(response) try: _validate_chapters_align_to_segments(result, segment_structure) except ChapterMarkersResponseFormatError: - logger.warning("chapter_markers_alignment_validation_failed") + log_warning(logger, "chapter_markers_alignment_validation_failed") raise return result diff --git a/episodic/llm/openai_api/utils.py b/episodic/llm/openai_api/utils.py index 2d4f796f..9dd96ecf 100644 --- a/episodic/llm/openai_api/utils.py +++ b/episodic/llm/openai_api/utils.py @@ -33,11 +33,11 @@ LLMTokenBudget, LLMTokenBudgetExceededError, ) -from episodic.logging import getLogger +from episodic.logging import LoggerHandle, getLogger, log_error -_log = getLogger(__name__) +_log: LoggerHandle = getLogger(__name__) -_log_override: contextvars.ContextVar[typ.Any | None] = contextvars.ContextVar( +_log_override: contextvars.ContextVar[LoggerHandle | None] = contextvars.ContextVar( "openai_adapter_log_override", default=None ) @@ -108,7 +108,9 @@ def _operation_label(operation: LLMProviderOperation | str | None) -> str: def _log_error_event(message: str, **fields: object) -> None: """Emit one JSON-encoded ERROR event with bounded diagnostic fields.""" effective_log = _log_override.get() or _log - effective_log.error(json.dumps({"event": message, **fields}, sort_keys=True)) + log_error( + effective_log, "%s", json.dumps({"event": message, **fields}, sort_keys=True) + ) def _is_positive_int(value: object) -> bool: diff --git a/episodic/logging.py b/episodic/logging.py index eb2055c7..ca0f9371 100644 --- a/episodic/logging.py +++ b/episodic/logging.py @@ -1,7 +1,6 @@ """Logging helpers for femtologging integration. -This module keeps the local logging configuration seam stable while exposing -the newer stdlib-aligned femtologging logger surface for current code. +This module owns the application's logging port over femtologging. Examples -------- @@ -9,7 +8,7 @@ >>> level, used_default = configure_logging("INFO") >>> logger = get_logger(__name__) ->>> logger.info("Started ingestion") +>>> log_info(logger, "Started ingestion") """ import enum @@ -17,7 +16,8 @@ import typing as typ import warnings -from femtologging import basicConfig, get_logger, getLogger +from femtologging import basicConfig +from femtologging import get_logger as _get_femtologger class LogLevel(enum.StrEnum): @@ -91,6 +91,16 @@ def configure_logging( class _SupportsConvenienceLog(typ.Protocol): """Protocol for loggers supporting stdlib-like femtologging methods.""" + def debug( + self, + message: str, + /, + *, + exc_info: object | None = None, + stack_info: bool = False, + ) -> None: + """Emit a DEBUG-level log record.""" + def info( self, message: str, @@ -121,6 +131,16 @@ def error( ) -> None: """Emit an ERROR-level log record.""" + def exception( + self, + message: str, + /, + *, + exc_info: object | None = None, + stack_info: bool = False, + ) -> None: + """Emit an ERROR-level record with exception information.""" + class _SupportsLogMethod(typ.Protocol): """Protocol for loggers exposing the stdlib-style `log` entry point.""" @@ -138,6 +158,36 @@ def log( type _CompatibleLogger = _SupportsConvenienceLog | _SupportsLogMethod +type _ConvenienceMethod = typ.Literal[ + "debug", + "info", + "warning", + "error", + "exception", +] +type _LogCall = tuple[int, _ConvenienceMethod] + + +class LoggerHandle: + """Opaque handle accepted by the Episodic logging port. + + Callers obtain a handle from :func:`get_logger` and emit records through + ``log_debug``, ``log_info``, ``log_warning``, ``log_error``, or + ``log_exception``. The private backend remains inaccessible so future + cross-cutting context is attached consistently at this port. + """ + + def __init__(self, logger: _CompatibleLogger) -> None: + """Wrap a compatible backend logger for use by port helpers.""" + self._logger = logger + + +def get_logger(name: str) -> LoggerHandle: + """Return an opaque logging-port handle for *name*.""" + return LoggerHandle(typ.cast("_CompatibleLogger", _get_femtologger(name))) + + +getLogger = get_logger # noqa: N816 # Preserve the stdlib-compatible constructor alias. def _format_message(template: str, args: tuple[object, ...]) -> str: @@ -145,8 +195,46 @@ def _format_message(template: str, args: tuple[object, ...]) -> str: return template % args if args else template +def _emit( + logger: LoggerHandle, + log_call: _LogCall, + message: str, + exc_info: object | None, +) -> None: + """Dispatch one pre-formatted message through the wrapped backend.""" + level, convenience_method = log_call + backend = logger._logger + try: + method = getattr( + typ.cast("_SupportsConvenienceLog", backend), convenience_method + ) + method(message, exc_info=exc_info, stack_info=False) + except (AttributeError, TypeError): # fmt: skip + typ.cast("_SupportsLogMethod", backend).log( + level, + message, + exc_info=exc_info, + stack_info=False, + ) + + +def log_debug( + logger: LoggerHandle, + template: str, + *args: object, + exc_info: object | None = None, +) -> None: + """Format and emit a DEBUG log message through the port.""" + _emit( + logger, + (logging.DEBUG, "debug"), + _format_message(template, args), + exc_info, + ) + + def log_info( - logger: _CompatibleLogger, + logger: LoggerHandle, template: str, *args: object, exc_info: object | None = None, @@ -155,9 +243,8 @@ def log_info( Parameters ---------- - logger : _CompatibleLogger - Logger instance that supports femtologging convenience methods or a - stdlib-style `log(...)` fallback. + logger : LoggerHandle + Opaque handle returned by :func:`get_logger`. template : str Percent-style format string for the log message. *args : object @@ -165,24 +252,16 @@ def log_info( exc_info : object | None, optional Exception info to attach to the log record. """ - message = _format_message(template, args) - try: - typ.cast("_SupportsConvenienceLog", logger).info( - message, - exc_info=exc_info, - stack_info=False, - ) - except (AttributeError, TypeError): # fmt: skip - typ.cast("_SupportsLogMethod", logger).log( - logging.INFO, - message, - exc_info=exc_info, - stack_info=False, - ) + _emit( + logger, + (logging.INFO, "info"), + _format_message(template, args), + exc_info, + ) def log_warning( - logger: _CompatibleLogger, + logger: LoggerHandle, template: str, *args: object, exc_info: object | None = None, @@ -191,9 +270,8 @@ def log_warning( Parameters ---------- - logger : _CompatibleLogger - Logger instance that supports femtologging convenience methods or a - stdlib-style `log(...)` fallback. + logger : LoggerHandle + Opaque handle returned by :func:`get_logger`. template : str Percent-style format string for the log message. *args : object @@ -201,24 +279,16 @@ def log_warning( exc_info : object | None, optional Exception info to attach to the log record. """ - message = _format_message(template, args) - try: - typ.cast("_SupportsConvenienceLog", logger).warning( - message, - exc_info=exc_info, - stack_info=False, - ) - except (AttributeError, TypeError): # fmt: skip - typ.cast("_SupportsLogMethod", logger).log( - logging.WARNING, - message, - exc_info=exc_info, - stack_info=False, - ) + _emit( + logger, + (logging.WARNING, "warning"), + _format_message(template, args), + exc_info, + ) def log_error( - logger: _CompatibleLogger, + logger: LoggerHandle, template: str, *args: object, exc_info: object | None = None, @@ -227,9 +297,8 @@ def log_error( Parameters ---------- - logger : _CompatibleLogger - Logger instance that supports femtologging convenience methods or a - stdlib-style `log(...)` fallback. + logger : LoggerHandle + Opaque handle returned by :func:`get_logger`. template : str Percent-style format string for the log message. *args : object @@ -237,28 +306,38 @@ def log_error( exc_info : object | None, optional Exception info to attach to the log record. """ - message = _format_message(template, args) - try: - typ.cast("_SupportsConvenienceLog", logger).error( - message, - exc_info=exc_info, - stack_info=False, - ) - except (AttributeError, TypeError): # fmt: skip - typ.cast("_SupportsLogMethod", logger).log( - logging.ERROR, - message, - exc_info=exc_info, - stack_info=False, - ) + _emit( + logger, + (logging.ERROR, "error"), + _format_message(template, args), + exc_info, + ) + + +def log_exception( + logger: LoggerHandle, + template: str, + *args: object, + exc_info: object | None = True, +) -> None: + """Format and emit an exception record with traceback information.""" + _emit( + logger, + (logging.ERROR, "exception"), + _format_message(template, args), + exc_info, + ) __all__ = ( "LogLevel", + "LoggerHandle", "configure_logging", "getLogger", "get_logger", + "log_debug", "log_error", + "log_exception", "log_info", "log_warning", ) diff --git a/episodic/observability.py b/episodic/observability.py index 6075b397..65807b6b 100644 --- a/episodic/observability.py +++ b/episodic/observability.py @@ -17,23 +17,32 @@ ``representation``, and ``pagination``; it drops all other attributes because callers may attach sensitive operation metadata. -:class:`episodic.metrics_ports.BoundedMetricsPort` is a deliberately narrower -structural subtype with ``dict[str, str]`` labels, retained because feature- -specific ports (such as :class:`episodic.qa.chrono.ChronoMetricsPort`) -historically extend it. Any adapter that satisfies :class:`MetricsPort` also -satisfies :class:`BoundedMetricsPort` for callers that build their label -dicts as concrete ``dict`` instances. +:class:`episodic.metrics_ports.BoundedMetricsPort` is a narrower structural +subtype with ``dict[str, str]`` labels for feature-specific ports. Any +adapter that satisfies :class:`MetricsPort` also satisfies +:class:`BoundedMetricsPort` for callers that build concrete ``dict`` labels. """ import dataclasses as dc -import logging +import json import time import typing as typ +from episodic.logging import LoggerHandle, get_logger, log_info + if typ.TYPE_CHECKING: from collections import abc as cabc +def _emit_structured_event( + logger: LoggerHandle, + event: str, + **fields: object, +) -> None: + """Emit one JSON-encoded observability event through the logging port.""" + log_info(logger, "%s", json.dumps({"event": event, **fields}, sort_keys=True)) + + class MetricsPort(typ.Protocol): """Bounded-cardinality metrics sink shared by adapters and services.""" @@ -155,9 +164,7 @@ def observe_value( # noqa: PLR6301 # No-op metrics intentionally retain no sta class StructuredLogMetrics: """Production metrics adapter that emits bounded structured observations.""" - logger: "_StructuredLogSink" = dc.field( # noqa: UP037 # Defined below its adapter. - default_factory=lambda: logging.getLogger(__name__), - ) + logger: LoggerHandle = dc.field(default_factory=lambda: get_logger(__name__)) def increment_counter( self, @@ -166,7 +173,9 @@ def increment_counter( labels: cabc.Mapping[str, str], ) -> None: """Emit one bounded counter observation.""" - self.logger.info("metric_counter", extra={"metric_name": name, **labels}) + _emit_structured_event( + self.logger, "metric_counter", metric_name=name, **labels + ) def observe_latency_ms( self, @@ -197,9 +206,12 @@ def _emit_value( labels: cabc.Mapping[str, str], ) -> None: """Emit a structured scalar metric event.""" - self.logger.info( + _emit_structured_event( + self.logger, event_name, - extra={"metric_name": name, "value": str(value), **labels}, + metric_name=name, + value=str(value), + **labels, ) @@ -248,19 +260,6 @@ def start_span( # noqa: PLR6301 # No-op tracer intentionally retains no state. return _NOOP_SPAN -class _StructuredLogSink(typ.Protocol): - """Logger surface required by :class:`StructuredLogTracer`.""" - - def info( - self, - message: str, - /, - *, - extra: cabc.Mapping[str, str], - ) -> None: - """Emit an INFO-level structured event.""" - - _SAFE_SPAN_ATTRIBUTES = frozenset({ "operation", "outcome", @@ -274,7 +273,7 @@ def info( class _StructuredLogSpan: """Complete a structured-log span with allow-listed attributes only.""" - logger: _StructuredLogSink + logger: LoggerHandle name: str attributes: dict[str, str] @@ -291,9 +290,11 @@ def __exit__( """Log completion without suppressing an operation exception.""" del exc_value, traceback event = "trace_span_completed" if exc_type is None else "trace_span_failed" - self.logger.info( + _emit_structured_event( + self.logger, event, - extra={"span_name": self.name, **self.attributes}, + span_name=self.name, + **self.attributes, ) return False @@ -312,9 +313,7 @@ class StructuredLogTracer: paths, and other sensitive metadata from log records. """ - logger: _StructuredLogSink = dc.field( - default_factory=lambda: logging.getLogger(__name__), - ) + logger: LoggerHandle = dc.field(default_factory=lambda: get_logger(__name__)) def start_span( self, @@ -328,9 +327,11 @@ def start_span( for key, value in attributes.items() if key in _SAFE_SPAN_ATTRIBUTES } - self.logger.info( + _emit_structured_event( + self.logger, "trace_span_started", - extra={"span_name": name, **safe_attributes}, + span_name=name, + **safe_attributes, ) return _StructuredLogSpan( logger=self.logger, diff --git a/episodic/orchestration/_types.py b/episodic/orchestration/_types.py index b7f686fe..431f64ea 100644 --- a/episodic/orchestration/_types.py +++ b/episodic/orchestration/_types.py @@ -3,32 +3,40 @@ import enum import json -from episodic.logging import getLogger +from episodic.logging import ( + getLogger, + log_debug, + log_error, + log_info, + log_warning, +) _log = getLogger(__name__) def _log_event(level: str, message: str, **fields: object) -> None: - """Emit one structured log event with a JSON fallback. - - Logger convenience methods (``debug``, ``info``, ...) only accept - ``exc_info`` / ``stack_info`` besides the message. Structured fields are - serialized into one JSON message when needed. - """ - log_method = getattr(_log, level) - allowed_kwargs = { - k: v for k, v in fields.items() if k in {"exc_info", "stack_info"} + """Emit one structured log event through the logging port.""" + exc_info = fields.get("exc_info") + extra_fields = { + key: value + for key, value in fields.items() + if key not in {"exc_info", "stack_info"} } - extra_fields = {k: v for k, v in fields.items() if k not in allowed_kwargs} if extra_fields: - payload = {"event": message, **extra_fields} - log_method(json.dumps(payload, sort_keys=True), **allowed_kwargs) - return - try: - log_method(message, **allowed_kwargs) - except TypeError: - payload = {"event": message} - log_method(json.dumps(payload, sort_keys=True), **allowed_kwargs) + message = json.dumps({"event": message, **extra_fields}, sort_keys=True) + + match level: + case "debug": + log_debug(_log, message, exc_info=exc_info) + case "info": + log_info(_log, message, exc_info=exc_info) + case "warning": + log_warning(_log, message, exc_info=exc_info) + case "error": + log_error(_log, message, exc_info=exc_info) + case _: + msg = f"Unsupported orchestration log level: ${level!r}" + raise ValueError(msg) class ActionKind(enum.StrEnum): diff --git a/episodic/qa/chrono.py b/episodic/qa/chrono.py index b5a26d78..473ce713 100644 --- a/episodic/qa/chrono.py +++ b/episodic/qa/chrono.py @@ -32,17 +32,18 @@ import asyncio import dataclasses as dc -import logging +import json import re import typing as typ import tei_rapporteur as _tei +from episodic.logging import get_logger, log_debug, log_warning from episodic.metrics_ports import BoundedMetricsPort, NoopBoundedMetrics from episodic.observability import MonotonicClockPort, PerfCounterClock SPOKEN_WORD_REGEX = r"[A-Za-z][A-Za-z0-9'-]*" -_log = logging.getLogger(__name__) +_log = get_logger(__name__) _WORD_PATTERN = re.compile(SPOKEN_WORD_REGEX) _DEFAULT_ESTIMATOR_NAME = "chrono-naive-word-count" _DEFAULT_ESTIMATOR_VERSION = "1" @@ -254,9 +255,16 @@ def _record_success( ) -> None: """Record success-only side effects for the estimator boundary.""" if result.metadata.spoken_word_count == 0: - _log.debug( - "Chrono: no spoken words found", - extra={"input_character_count": len(request.script_tei_xml)}, + log_debug( + _log, + "%s", + json.dumps( + { + "event": "chrono_no_spoken_words", + "input_character_count": len(request.script_tei_xml), + }, + sort_keys=True, + ), ) labels = {"outcome": "success"} self.metrics.increment_counter(_METRIC_EVALUATIONS, labels=labels) @@ -274,7 +282,8 @@ def _record_validation_error( ) -> None: """Record validation-error side effects for the estimator boundary.""" labels = {"outcome": "error", "error_type": "ValueError"} - _log.warning( + log_warning( + _log, "Chrono TEI validation failed; input_character_count=%s", len(request.script_tei_xml), exc_info=True, diff --git a/episodic/qa/chrono_langgraph.py b/episodic/qa/chrono_langgraph.py index 4a611204..38637883 100644 --- a/episodic/qa/chrono_langgraph.py +++ b/episodic/qa/chrono_langgraph.py @@ -22,17 +22,19 @@ """ import dataclasses as dc -import logging +import json import typing as typ from langgraph.graph import END, START, StateGraph +from episodic.logging import get_logger, log_error, log_exception + from .chrono import ( # noqa: TC001 # LangGraph evaluates state annotations at runtime. ChronoEvaluationRequest, ChronoRuntimeEstimate, ) -_log = logging.getLogger(__name__) +_log = get_logger(__name__) if typ.TYPE_CHECKING: from langgraph.graph.state import CompiledStateGraph @@ -66,22 +68,34 @@ async def chrono_node( state: ChronoGraphState, ) -> dict[str, ChronoRuntimeEstimate]: if state.chrono_request is None: - _log.error( - "Chrono graph node missing required request; has_chrono_result=%s", - state.chrono_result is not None, - extra={"has_chrono_result": state.chrono_result is not None}, + log_error( + _log, + "%s", + json.dumps( + { + "event": "chrono_graph_request_missing", + "has_chrono_result": state.chrono_result is not None, + }, + sort_keys=True, + ), ) msg = "chrono_request" raise KeyError(msg) try: result = await evaluator.evaluate(state.chrono_request) except Exception: - _log.exception( - "Chrono graph node evaluation failed; input_character_count=%s", - len(state.chrono_request.script_tei_xml), - extra={ - "input_character_count": len(state.chrono_request.script_tei_xml) - }, + log_exception( + _log, + "%s", + json.dumps( + { + "event": "chrono_graph_evaluation_failed", + "input_character_count": len( + state.chrono_request.script_tei_xml + ), + }, + sort_keys=True, + ), ) raise return {"chrono_result": result} diff --git a/episodic/worker/runtime.py b/episodic/worker/runtime.py index 098de9ad..70643bc6 100644 --- a/episodic/worker/runtime.py +++ b/episodic/worker/runtime.py @@ -24,7 +24,7 @@ from celery import Celery -from episodic.logging import get_logger +from episodic.logging import get_logger, log_exception, log_info from .tasks import SCAFFOLD_TASK_WORKLOADS, WorkerDependencies, register_scaffold_tasks from .topology import DEFAULT_WORKER_TOPOLOGY, WorkerTopology, WorkloadClass @@ -294,13 +294,8 @@ def _build_task_routes( if task_workloads is None: task_workloads = SCAFFOLD_TASK_WORKLOADS - def _log_info(message: str, *args: object) -> None: - try: - logger.info(message, *args) - except TypeError: - logger.info(message % args) - - _log_info( + log_info( + logger, "Building Celery worker task routes for %s tasks.", len(task_workloads), ) @@ -308,25 +303,16 @@ def _log_info(message: str, *args: object) -> None: task_routes = topology.task_routes(task_workloads) except (TypeError, ValueError) as exc: validation_error = str(exc) - log_exception = logger.exception - try: - log_exception( - ( - "Celery worker task route validation failed for " - "tasks=%r, workloads=%r: %s" - ), - tuple(task_workloads), - tuple(task_workloads.values()), - validation_error, - ) - except TypeError: - log_exception( - "Celery worker task route validation failed for tasks=" - f"{tuple(task_workloads)!r}, workloads=" - f"{tuple(task_workloads.values())!r}: {validation_error}", - ) + log_exception( + logger, + "Celery worker task route validation failed for tasks=%r, workloads=%r: %s", + tuple(task_workloads), + tuple(task_workloads.values()), + validation_error, + ) raise - _log_info( + log_info( + logger, "Built Celery worker task routes for %s tasks.", len(task_routes), ) diff --git a/pyproject.toml b/pyproject.toml index eacc3597..96724226 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -63,6 +63,9 @@ extend-exclude = [ "scripts/typos_rollout_cache.py", ] +[tool.ty.src] +exclude = ["tests/fixtures/typecheck/"] + [tool.ruff.lint] select = [ "F", # Pyflakes rules @@ -748,6 +751,11 @@ full_name = [ ] reason = "Metrics and tracing adapters implement runtime-selected observability protocols and their bounded emission path." +[[tool.skylos.dead_code.entrypoints]] +type = "function" +full_name = ["episodic.observability._emit_structured_event"] +reason = "StructuredLogMetrics and StructuredLogTracer invoke this shared port-emission helper." + [[tool.skylos.dead_code.entrypoints]] type = "variable" full_name = [ @@ -785,6 +793,41 @@ names = [] [tool.hecate] root_packages = ["episodic"] default_rule_id = "ARCH001" +include_external_packages = true + +[[tool.hecate.groups]] +name = "logging_port" +prefixes = ["episodic.logging"] +allowed = ["logging_port", "logging_backend"] + +[[tool.hecate.groups]] +name = "logging_backend" +prefixes = ["femtologging"] +allowed = ["logging_backend"] + +[[tool.hecate.groups]] +name = "external_libraries" +prefixes = [ + "alembic", + "asyncpg", + "celery", + "eventlet", + "falcon", + "gevent", + "granian", + "httpx", + "kombu", + "langgraph", + "openai", + "psycopg", + "py_pglite", + "pydantic", + "sqlalchemy", + "tei_rapporteur", + "tenacity", + "yaml", +] +allowed = ["external_libraries"] [[tool.hecate.groups]] name = "composition_root" @@ -793,7 +836,9 @@ allowed = [ "application", "composition_root", "domain_ports", + "external_libraries", "inbound_adapter", + "logging_port", "outbound_adapter", ] @@ -824,7 +869,7 @@ prefixes = [ "episodic.llm.ports", "episodic.metrics_ports", ] -allowed = ["domain_ports"] +allowed = ["domain_ports", "external_libraries", "logging_port"] [[tool.hecate.groups]] name = "application" @@ -840,7 +885,7 @@ prefixes = [ "episodic.generation", "episodic.orchestration", ] -allowed = ["application", "domain_ports"] +allowed = ["application", "domain_ports", "external_libraries", "logging_port"] [[tool.hecate.groups]] name = "inbound_adapter" @@ -849,7 +894,13 @@ prefixes = [ "episodic.worker.tasks", "episodic.worker.topology", ] -allowed = ["inbound_adapter", "application", "domain_ports"] +allowed = [ + "inbound_adapter", + "application", + "domain_ports", + "external_libraries", + "logging_port", +] [[tool.hecate.groups]] name = "outbound_adapter" @@ -862,7 +913,13 @@ prefixes = [ "episodic.llm.openai_adapter", "episodic.llm.openai_client", ] -allowed = ["outbound_adapter", "application", "domain_ports"] +allowed = [ + "outbound_adapter", + "application", + "domain_ports", + "external_libraries", + "logging_port", +] [build-system] requires = ["uv_build>=0.12.5,<0.13.0"] diff --git a/tests/__snapshots__/test_logging.ambr b/tests/__snapshots__/test_logging.ambr index aa34304e..e63939db 100644 --- a/tests/__snapshots__/test_logging.ambr +++ b/tests/__snapshots__/test_logging.ambr @@ -1,6 +1,12 @@ # serializer version: 1 # name: test_log_wrappers_delegate_through_convenience_methods list([ + tuple( + , + 'Loading 3 documents', + None, + False, + ), tuple( , 'Loaded 3 documents', @@ -19,10 +25,22 @@ RuntimeError('boom'), False, ), + tuple( + , + 'Failed capture job-2', + True, + False, + ), ]) # --- # name: test_log_wrappers_fall_back_to_logger_log_when_needed list([ + tuple( + 10, + 'Loading 3 documents', + None, + False, + ), tuple( 20, 'Loaded 3 documents', @@ -41,6 +59,12 @@ RuntimeError('boom'), False, ), + tuple( + 40, + 'Failed capture job-2', + True, + False, + ), ]) # --- # name: test_stdlib_style_logger_methods_emit_to_python_handlers diff --git a/tests/architecture_hecate_config.py b/tests/architecture_hecate_config.py index e305a99e..9af3fa10 100644 --- a/tests/architecture_hecate_config.py +++ b/tests/architecture_hecate_config.py @@ -18,6 +18,7 @@ import subprocess # noqa: S404 # Tests exercise the Hecate CLI contract. import sys import textwrap +import typing as typ from pathlib import Path FIXTURE_ROOT: Path = Path(__file__).resolve().parent / "fixtures" / "architecture" @@ -38,7 +39,9 @@ "domain", ) BARREL_OUTBOUND_FIXTURE = "api_imports_star_reexported_outbound_adapter" +LOGGING_PORT_FIXTURE = "femtologging_outside_logging_port" HECATE_TIMEOUT_SECONDS = 60 +type FixturePolicyVariant = typ.Literal["default", "external_logging"] class HecateInvocationError(RuntimeError): @@ -63,7 +66,12 @@ def __init__( super().__init__(message) -def write_fixture_config(tmp_path: Path, package_name: str) -> Path: +def write_fixture_config( + tmp_path: Path, + package_name: str, + *, + policy_variant: FixturePolicyVariant = "default", +) -> Path: """Write a Hecate config for one architecture fixture package. Parameters @@ -90,6 +98,7 @@ def write_fixture_config(tmp_path: Path, package_name: str) -> Path: _fixture_config( package, treats_package_barrel_as_outbound=package_name == BARREL_OUTBOUND_FIXTURE, + policy_variant=policy_variant, ), encoding="utf-8", ) @@ -205,8 +214,15 @@ def run_hecate_production_check( raise HecateInvocationError from exc -def _fixture_config(package: str, *, treats_package_barrel_as_outbound: bool) -> str: +def _fixture_config( + package: str, + *, + treats_package_barrel_as_outbound: bool, + policy_variant: FixturePolicyVariant, +) -> str: """Return fixture-specific Hecate TOML.""" + if policy_variant == "external_logging": + return _external_logging_fixture_config(package) outbound_prefixes = ( f'"{package}.storage", "{package}"' if treats_package_barrel_as_outbound @@ -251,6 +267,87 @@ def _fixture_config(package: str, *, treats_package_barrel_as_outbound: bool) -> ) +def _external_logging_fixture_config(package: str) -> str: + """Return a fixture policy that enforces the femtologging boundary.""" + return textwrap.dedent( + f"""\ + [tool.hecate] + root_packages = ["{package}"] + default_rule_id = "ARCH001" + include_external_packages = true + + [[tool.hecate.groups]] + name = "logging_port" + prefixes = ["{package}.logging"] + allowed = ["logging_port", "logging_backend"] + + [[tool.hecate.groups]] + name = "logging_backend" + prefixes = ["femtologging"] + allowed = ["logging_backend"] + + [[tool.hecate.groups]] + name = "external_libraries" + prefixes = [ + "alembic", + "celery", + "falcon", + "httpx", + "langgraph", + "openai", + "pydantic", + "sqlalchemy", + ] + allowed = ["external_libraries"] + + [[tool.hecate.groups]] + name = "composition_root" + prefixes = ["{package}.runtime"] + allowed = [ + "application", + "composition_root", + "domain", + "external_libraries", + "inbound_adapter", + "logging_port", + "outbound_adapter", + ] + + [[tool.hecate.groups]] + name = "domain" + prefixes = ["{package}.domain"] + allowed = ["domain", "external_libraries", "logging_port"] + + [[tool.hecate.groups]] + name = "application" + prefixes = ["{package}.service"] + allowed = ["application", "domain", "external_libraries", "logging_port"] + + [[tool.hecate.groups]] + name = "inbound_adapter" + prefixes = ["{package}.api"] + allowed = [ + "application", + "domain", + "external_libraries", + "inbound_adapter", + "logging_port", + ] + + [[tool.hecate.groups]] + name = "outbound_adapter" + prefixes = ["{package}.storage"] + allowed = [ + "application", + "domain", + "external_libraries", + "logging_port", + "outbound_adapter", + ] + """ + ) + + def _toml_string_array(values: tuple[str, ...]) -> str: """Return a TOML array of quoted strings.""" return "[" + ", ".join(f'"{value}"' for value in values) + "]" diff --git a/tests/features/architecture_enforcement.feature b/tests/features/architecture_enforcement.feature index efa6a92c..9947edba 100644 --- a/tests/features/architecture_enforcement.feature +++ b/tests/features/architecture_enforcement.feature @@ -20,3 +20,11 @@ Feature: Architecture enforcement Given the architecture fixture package "composition_root_allows_wiring" When the architecture checker runs Then the architecture check passes + + Scenario: A direct femtologging import bypassing the logging port is rejected + Given the architecture fixture package "femtologging_outside_logging_port" + When the architecture checker runs + Then the architecture check fails + And the architecture diagnostic mentions "ARCH001" + And the architecture diagnostic mentions "api" + And the architecture diagnostic mentions "femtologging" diff --git a/tests/fixtures/architecture/femtologging_outside_logging_port/__init__.py b/tests/fixtures/architecture/femtologging_outside_logging_port/__init__.py new file mode 100644 index 00000000..eacb6b7f --- /dev/null +++ b/tests/fixtures/architecture/femtologging_outside_logging_port/__init__.py @@ -0,0 +1 @@ +"""Fixture package for the femtologging import boundary.""" diff --git a/tests/fixtures/architecture/femtologging_outside_logging_port/api.py b/tests/fixtures/architecture/femtologging_outside_logging_port/api.py new file mode 100644 index 00000000..4c0ad55f --- /dev/null +++ b/tests/fixtures/architecture/femtologging_outside_logging_port/api.py @@ -0,0 +1,5 @@ +"""Forbidden direct femtologging import from an inbound adapter.""" + +from femtologging import get_logger + +logger = get_logger(__name__) diff --git a/tests/fixtures/architecture/femtologging_outside_logging_port/logging.py b/tests/fixtures/architecture/femtologging_outside_logging_port/logging.py new file mode 100644 index 00000000..adfd17ae --- /dev/null +++ b/tests/fixtures/architecture/femtologging_outside_logging_port/logging.py @@ -0,0 +1,5 @@ +"""Sanctioned fixture logging port that owns the femtologging import.""" + +from femtologging import get_logger + +logger = get_logger(__name__) diff --git a/tests/fixtures/llm.py b/tests/fixtures/llm.py index c40c6545..be9707e3 100644 --- a/tests/fixtures/llm.py +++ b/tests/fixtures/llm.py @@ -19,6 +19,7 @@ OpenAICompatibleLLMAdapter, OpenAICompatibleLLMConfig, ) +from episodic.logging import LoggerHandle, LogLevel if typ.TYPE_CHECKING: import collections.abc as cabc @@ -42,8 +43,18 @@ def __init__(self) -> None: """Initialise an empty message list.""" self.messages: list[str] = [] - def error(self, message: str) -> None: + def log( + self, + level: int | LogLevel, + message: str, + /, + *, + exc_info: object | None = None, + stack_info: bool = False, + ) -> None: """Record one ERROR-level log message.""" + del exc_info, stack_info + assert level == 40, "OpenAI adapter failures must be ERROR logs" self.messages += [message] @@ -62,7 +73,7 @@ def openai_log_spy() -> cabc.Generator[_OpenAILogSpy]: from episodic.llm.openai_api import utils as openai_utils spy = _OpenAIAdapterLogSpy() - token = openai_utils._log_override.set(spy) + token = openai_utils._log_override.set(LoggerHandle(spy)) yield spy openai_utils._log_override.reset(token) diff --git a/tests/fixtures/typecheck/logging_handle_direct_call.py b/tests/fixtures/typecheck/logging_handle_direct_call.py new file mode 100644 index 00000000..019f00c3 --- /dev/null +++ b/tests/fixtures/typecheck/logging_handle_direct_call.py @@ -0,0 +1,9 @@ +"""Negative typing fixture for the logging-port direct-call boundary.""" + +from episodic.logging import get_logger + + +def direct_logger_call_is_not_permitted() -> None: + """Demonstrate the rejected raw logger method surface.""" + logger = get_logger(__name__) + logger.info("This call must remain a type error.") diff --git a/tests/steps/test_architecture_enforcement_steps.py b/tests/steps/test_architecture_enforcement_steps.py index c9061d64..b0dbf237 100644 --- a/tests/steps/test_architecture_enforcement_steps.py +++ b/tests/steps/test_architecture_enforcement_steps.py @@ -16,7 +16,11 @@ from pathlib import Path # noqa: TC003 # pytest-bdd evaluates step annotations. import pytest -from architecture_hecate_config import run_hecate_fixture_check, write_fixture_config +from architecture_hecate_config import ( + LOGGING_PORT_FIXTURE, + run_hecate_fixture_check, + write_fixture_config, +) from pytest_bdd import given, parsers, scenario, then, when @@ -58,6 +62,14 @@ def test_composition_root_wiring_is_accepted() -> None: """Run the composition-root acceptance scenario.""" +@scenario( + "../features/architecture_enforcement.feature", + "A direct femtologging import bypassing the logging port is rejected", +) +def test_direct_femtologging_import_is_rejected() -> None: + """Run the femtologging-boundary scenario.""" + + @given(parsers.parse('the architecture fixture package "{package_name}"')) def architecture_fixture_package( context: ArchitectureContext, @@ -70,7 +82,16 @@ def architecture_fixture_package( @when("the architecture checker runs") def architecture_checker_runs(context: ArchitectureContext, tmp_path: Path) -> None: """Run the architecture checker through its command-line entrypoint.""" - config_path = write_fixture_config(tmp_path, context.package_name) + policy_variant = ( + "external_logging" + if context.package_name == LOGGING_PORT_FIXTURE + else "default" + ) + config_path = write_fixture_config( + tmp_path, + context.package_name, + policy_variant=policy_variant, + ) context.completed_process = run_hecate_fixture_check( context.package_name, config_path, diff --git a/tests/test_architecture_enforcement.py b/tests/test_architecture_enforcement.py index 8e818765..b00fee2b 100644 --- a/tests/test_architecture_enforcement.py +++ b/tests/test_architecture_enforcement.py @@ -12,6 +12,7 @@ import pytest from architecture_hecate_config import ( + LOGGING_PORT_FIXTURE, run_hecate_fixture_check, run_hecate_production_check, write_fixture_config, @@ -83,6 +84,14 @@ "tests.fixtures.architecture.explicit_empty_all.storage", ), ), + ( + LOGGING_PORT_FIXTURE, + ( + "ARCH001", + "tests.fixtures.architecture.femtologging_outside_logging_port.api", + "femtologging", + ), + ), ], ) def test_checker_reports_fixture_boundary_violations( @@ -91,7 +100,14 @@ def test_checker_reports_fixture_boundary_violations( tmp_path: Path, ) -> None: """Forbidden fixture imports produce stable architecture diagnostics.""" - config_path = write_fixture_config(tmp_path, package_name) + policy_variant = ( + "external_logging" if package_name == LOGGING_PORT_FIXTURE else "default" + ) + config_path = write_fixture_config( + tmp_path, + package_name, + policy_variant=policy_variant, + ) completed_process = run_hecate_fixture_check(package_name, config_path) diff --git a/tests/test_architecture_hecate_config.py b/tests/test_architecture_hecate_config.py index a4b06d88..aad1bb30 100644 --- a/tests/test_architecture_hecate_config.py +++ b/tests/test_architecture_hecate_config.py @@ -14,6 +14,7 @@ from architecture_hecate_config import ( BARREL_OUTBOUND_FIXTURE, HECATE_TIMEOUT_SECONDS, + LOGGING_PORT_FIXTURE, REPO_ROOT, HecateInvocationError, run_hecate_fixture_check, @@ -106,6 +107,31 @@ def test_fixture_config_writes_expected_toml_shape(tmp_path: Path) -> None: ], "outbound_adapter group must allow outbound, application, and domain imports" +def test_external_logging_fixture_config_enforces_the_port_boundary( + tmp_path: Path, +) -> None: + """The opt-in fixture policy tracks external imports and isolates femtologging.""" + package = f"tests.fixtures.architecture.{LOGGING_PORT_FIXTURE}" + config = _read_fixture_config( + tmp_path, + LOGGING_PORT_FIXTURE, + policy_variant="external_logging", + ) + + assert _hecate_config(config)["include_external_packages"] is True, ( + "external logging fixtures must analyse third-party imports" + ) + assert _group_prefixes(config, "logging_port") == [f"{package}.logging"], ( + "logging port must match before generic fixture groups" + ) + assert _group_prefixes(config, "logging_backend") == ["femtologging"], ( + "femtologging must have a dedicated backend group" + ) + assert "logging_backend" not in _group_allowed(config, "inbound_adapter"), ( + "inbound adapters must not import the raw logging backend" + ) + + @pytest.mark.parametrize( "error_case", [ @@ -277,9 +303,18 @@ def capture_run( ) -def _read_fixture_config(tmp_path: Path, package_name: str) -> dict[str, object]: +def _read_fixture_config( + tmp_path: Path, + package_name: str, + *, + policy_variant: typ.Literal["default", "external_logging"] = "default", +) -> dict[str, object]: """Write and parse the fixture Hecate config.""" - config_path = write_fixture_config(tmp_path, package_name) + config_path = write_fixture_config( + tmp_path, + package_name, + policy_variant=policy_variant, + ) return tomllib.loads(config_path.read_text(encoding="utf-8")) diff --git a/tests/test_chrono.py b/tests/test_chrono.py index aa74d5d5..35ac6dc3 100644 --- a/tests/test_chrono.py +++ b/tests/test_chrono.py @@ -270,13 +270,15 @@ def test_chrono_estimator_propagates_tei_validation_errors( warnings: list[tuple[str, tuple[object, ...], dict[str, object]]] = [] def capture_warning( + logger: object, msg: str, *args: object, **kwargs: object, ) -> None: + del logger warnings.append((msg, args, kwargs)) - monkeypatch.setattr("episodic.qa.chrono._log.warning", capture_warning) + monkeypatch.setattr("episodic.qa.chrono.log_warning", capture_warning) with pytest.raises(ValueError, match=message): ChronoRuntimeEstimator(metrics=metrics, clock=clock).estimate(request) diff --git a/tests/test_chrono_langgraph.py b/tests/test_chrono_langgraph.py index addb0542..fa2a7008 100644 --- a/tests/test_chrono_langgraph.py +++ b/tests/test_chrono_langgraph.py @@ -2,6 +2,7 @@ import asyncio import dataclasses as dc +import json import typing as typ import pytest @@ -97,21 +98,23 @@ async def test_chrono_node_logs_missing_request( errors: list[tuple[str, tuple[object, ...], dict[str, object]]] = [] def capture_error( + logger: object, msg: str, *args: object, **kwargs: object, ) -> None: + del logger errors.append((msg, args, kwargs)) - monkeypatch.setattr("episodic.qa.chrono_langgraph._log.error", capture_error) + monkeypatch.setattr("episodic.qa.chrono_langgraph.log_error", capture_error) with pytest.raises(KeyError, match="chrono_request"): await graph.ainvoke(ChronoGraphState()) assert errors == [ ( - "Chrono graph node missing required request; has_chrono_result=%s", - (False,), - {"extra": {"has_chrono_result": False}}, + "%s", + ('{"event": "chrono_graph_request_missing", "has_chrono_result": false}',), + {}, ) ], "Expected values to match" @@ -157,26 +160,36 @@ async def test_chrono_node_logs_evaluation_failure( exceptions: list[tuple[str, tuple[object, ...], dict[str, object]]] = [] def capture_exception( + logger: object, msg: str, *args: object, **kwargs: object, ) -> None: + del logger exceptions.append((msg, args, kwargs)) monkeypatch.setattr( - "episodic.qa.chrono_langgraph._log.exception", + "episodic.qa.chrono_langgraph.log_exception", capture_exception, ) with pytest.raises(ValueError, match="bad TEI"): await graph.ainvoke(ChronoGraphState(chrono_request=request)) - assert exceptions == [ + expected_error_event = json.dumps( + { + "event": "chrono_graph_evaluation_failed", + "input_character_count": len(request.script_tei_xml), + }, + sort_keys=True, + ) + expected_exceptions = [ ( - "Chrono graph node evaluation failed; input_character_count=%s", - (len(request.script_tei_xml),), - {"extra": {"input_character_count": len(request.script_tei_xml)}}, + "%s", + (expected_error_event,), + {}, ) - ], "Expected values to match" + ] + assert exceptions == expected_exceptions, "Expected values to match" @pytest.mark.asyncio diff --git a/tests/test_interpreter_executor_observability.py b/tests/test_interpreter_executor_observability.py index c7599604..faf8e152 100644 --- a/tests/test_interpreter_executor_observability.py +++ b/tests/test_interpreter_executor_observability.py @@ -3,11 +3,13 @@ import concurrent.futures as cf import contextlib import dataclasses as dc +import json import typing as typ import pytest import episodic.concurrent_interpreters as ci +from episodic.logging import LoggerHandle, LogLevel from tests.conftest import square_executor_value as _square if typ.TYPE_CHECKING: @@ -87,6 +89,19 @@ def exception(self, message: str, **kwargs: object) -> None: del kwargs self.messages.append(message) + def log( + self, + level: int | LogLevel, + message: str, + /, + *, + exc_info: object | None = None, + stack_info: bool = False, + ) -> None: + """Record a fallback logger call.""" + del level, exc_info, stack_info + self.messages.append(message) + @pytest.mark.asyncio async def test_interpreter_executor_records_lifecycle_observability( @@ -101,7 +116,7 @@ async def test_interpreter_executor_records_lifecycle_observability( "_create_interpreter_pool_executor", lambda max_workers: cf.ThreadPoolExecutor(max_workers=max_workers), ) - monkeypatch.setattr(ci, "_log", logger) + monkeypatch.setattr(ci, "_log", LoggerHandle(logger)) executor = ci.InterpreterPoolCpuTaskExecutor( max_workers=1, metrics=metrics, @@ -131,12 +146,10 @@ async def test_interpreter_executor_records_lifecycle_observability( pytest.approx(25.0), {"outcome": "success"}, ) in metrics.observations, "shutdown latency metric must record 25 ms" - assert "Created interpreter-pool executor" in logger.messages, ( - "creation log must identify the interpreter-pool executor" - ) - assert "Shut down interpreter-pool executor" in logger.messages, ( - "shutdown log must identify the interpreter-pool executor" - ) + assert {json.loads(message)["event"] for message in logger.messages} >= { + "interpreter_pool_executor_created", + "interpreter_pool_executor_shutdown", + }, "creation log must identify the interpreter-pool executor" def test_builder_records_executor_selection_metrics( diff --git a/tests/test_logging.py b/tests/test_logging.py index 679c9d40..9e664b80 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -53,6 +53,23 @@ def info( stack_info=stack_info, ) + # pylint: disable-next=too-many-arguments # mirrors stdlib/femtologging call signature + def debug( + self, + message: str, + /, + *, + exc_info: object | None = None, + stack_info: bool = False, + ) -> None: + """Record a DEBUG-level call.""" + self._record( + episodic_logging.LogLevel.DEBUG, + message, + exc_info=exc_info, + stack_info=stack_info, + ) + # pylint: disable-next=too-many-arguments # mirrors stdlib/femtologging call signature def warning( self, @@ -87,6 +104,23 @@ def error( stack_info=stack_info, ) + # pylint: disable-next=too-many-arguments # mirrors stdlib/femtologging call signature + def exception( + self, + message: str, + /, + *, + exc_info: object | None = None, + stack_info: bool = False, + ) -> None: + """Record an exception-level call.""" + self._record( + episodic_logging.LogLevel.ERROR, + message, + exc_info=exc_info, + stack_info=stack_info, + ) + class _LogOnlySpyLogger: """Collect low-level log calls through a stdlib-style `log` method only.""" @@ -228,9 +262,11 @@ def test_log_wrappers_delegate_through_convenience_methods( snapshot: SnapshotAssertion, ) -> None: """Compatibility helpers should preserve percent-style formatting semantics.""" - logger = _SpyLogger() + spy_logger = _SpyLogger() + logger = episodic_logging.LoggerHandle(spy_logger) err = RuntimeError("boom") + episodic_logging.log_debug(logger, "Loading %s documents", 3) episodic_logging.log_info(logger, "Loaded %s documents", 3) episodic_logging.log_warning(logger, "Potential issue in %s", "ingestion") episodic_logging.log_error( @@ -239,13 +275,17 @@ def test_log_wrappers_delegate_through_convenience_methods( "job-1", exc_info=err, ) + episodic_logging.log_exception(logger, "Failed capture %s", "job-2") - assert logger.calls == snapshot, "convenience-wrapper calls must match the snapshot" + assert spy_logger.calls == snapshot, ( + "convenience-wrapper calls must match the snapshot" + ) def test_log_wrappers_raise_type_error_on_mismatched_format() -> None: """Compatibility helpers should propagate `TypeError` from formatting.""" - logger = _SpyLogger() + spy_logger = _SpyLogger() + logger = episodic_logging.LoggerHandle(spy_logger) with pytest.raises( TypeError, @@ -253,7 +293,7 @@ def test_log_wrappers_raise_type_error_on_mismatched_format() -> None: ): episodic_logging.log_info(logger, "Loaded %s documents for %s", 3) - assert logger.calls == [], ( # pylint: disable=use-implicit-booleaness-not-comparison # The explicit empty-list comparison documents the expected collection value. + assert spy_logger.calls == [], ( # pylint: disable=use-implicit-booleaness-not-comparison # The explicit empty-list comparison documents the expected collection value. "expected no log calls after TypeError" ) @@ -262,9 +302,11 @@ def test_log_wrappers_fall_back_to_logger_log_when_needed( snapshot: SnapshotAssertion, ) -> None: """Compatibility helpers should support loggers that only expose `log()`.""" - logger = _LogOnlySpyLogger() + spy_logger = _LogOnlySpyLogger() + logger = episodic_logging.LoggerHandle(spy_logger) err = RuntimeError("boom") + episodic_logging.log_debug(logger, "Loading %s documents", 3) episodic_logging.log_info(logger, "Loaded %s documents", 3) episodic_logging.log_warning(logger, "Potential issue in %s", "ingestion") episodic_logging.log_error( @@ -273,8 +315,9 @@ def test_log_wrappers_fall_back_to_logger_log_when_needed( "job-1", exc_info=err, ) + episodic_logging.log_exception(logger, "Failed capture %s", "job-2") - assert logger.calls == snapshot, "fallback logger calls must match the snapshot" + assert spy_logger.calls == snapshot, "fallback logger calls must match the snapshot" def test_femtologging_exposes_stdlib_style_logger_surface() -> None: @@ -298,8 +341,8 @@ def test_femtologging_exposes_stdlib_style_logger_surface() -> None: assert hasattr(logger, method_name), method_name -def test_episodic_logging_get_logger_reexport_matches_femtologging_surface() -> None: - """Episodic logging should re-export the stdlib-style logger constructor.""" +def test_episodic_logging_get_logger_returns_opaque_handle() -> None: + """Episodic logging should hide the raw femtologging logger surface.""" logger = episodic_logging.getLogger("tests.logging.surface") for method_name in ( "debug", @@ -310,10 +353,7 @@ def test_episodic_logging_get_logger_reexport_matches_femtologging_surface() -> "exception", "isEnabledFor", ): - assert hasattr(logger, method_name), method_name - assert logger.isEnabledFor("INFO") is True, ( - "re-exported logger must report INFO as enabled" - ) + assert not hasattr(logger, method_name), method_name def _raise_logged_exception() -> None: diff --git a/tests/test_logging_port_enforcement.py b/tests/test_logging_port_enforcement.py new file mode 100644 index 00000000..a9e2a678 --- /dev/null +++ b/tests/test_logging_port_enforcement.py @@ -0,0 +1,58 @@ +"""Regression tests for logging-port call-site enforcement.""" + +import pathlib as pl +import re +import shutil +import subprocess # noqa: S404 # The test invokes a fixed local typechecker command. + +REPOSITORY_ROOT = pl.Path(__file__).resolve().parents[1] +DIRECT_CALL_FIXTURE = ( + REPOSITORY_ROOT + / "tests" + / "fixtures" + / "typecheck" + / "logging_handle_direct_call.py" +) +DIRECT_LOGGER_CALL_PATTERN = re.compile( + r"\b(?:logger|_log|_logger|effective_log)\.(?:debug|info|warning|error|critical|log)\(" +) + + +def test_typechecker_rejects_direct_logger_handle_calls() -> None: + """The opaque handle rejects raw level-method calls under ty.""" + uv_executable = shutil.which("uv") + assert uv_executable is not None, "Expected uv to run the pinned ty release." + completed_process = subprocess.run( # noqa: S603 # Static local command and fixture path. + [ + uv_executable, + "tool", + "run", + "ty==0.0.32", + "check", + str(DIRECT_CALL_FIXTURE), + ], + check=False, + capture_output=True, + cwd=REPOSITORY_ROOT, + text=True, + timeout=30, + ) + + rendered = f"{completed_process.stdout}\n{completed_process.stderr}" + assert completed_process.returncode != 0, rendered + assert "info" in rendered, rendered + assert "LoggerHandle" in rendered, rendered + + +def test_production_logger_calls_use_the_logging_port() -> None: + """Production modules must not call logger level methods directly.""" + offending_paths = { + path.relative_to(REPOSITORY_ROOT).as_posix() + for path in (REPOSITORY_ROOT / "episodic").glob("**/*.py") + if path != REPOSITORY_ROOT / "episodic" / "logging.py" + and DIRECT_LOGGER_CALL_PATTERN.search(path.read_text(encoding="utf-8")) + } + + assert not offending_paths, ( + f"Logger level methods bypass the logging port in: {sorted(offending_paths)!r}" + ) diff --git a/tests/test_observability.py b/tests/test_observability.py index 09771fad..70c8b1f6 100644 --- a/tests/test_observability.py +++ b/tests/test_observability.py @@ -1,8 +1,10 @@ """Focused tests for synchronous tracing adapters.""" import dataclasses as dc +import json import typing as typ +from episodic.logging import LoggerHandle, LogLevel from episodic.observability import ( NoopTracer, RecordingTracer, @@ -10,9 +12,6 @@ StructuredLogTracer, ) -if typ.TYPE_CHECKING: - from collections import abc as cabc - @dc.dataclass(slots=True) class _RecordingLogger: @@ -20,9 +19,21 @@ class _RecordingLogger: events: list[tuple[str, dict[str, str]]] = dc.field(default_factory=list) - def info(self, message: str, /, *, extra: cabc.Mapping[str, str]) -> None: + def log( + self, + level: int | LogLevel, + message: str, + /, + *, + exc_info: object | None = None, + stack_info: bool = False, + ) -> None: """Record a structured INFO event.""" - self.events.append((message, dict(extra))) + del exc_info, stack_info + assert level == 20, "structured observability events must be INFO logs" + payload = json.loads(message) + event = typ.cast("str", payload.pop("event")) + self.events.append((event, typ.cast("dict[str, str]", payload))) def test_recording_tracer_preserves_span_details_and_completion() -> None: @@ -43,7 +54,8 @@ def test_recording_tracer_preserves_span_details_and_completion() -> None: def test_structured_log_tracer_allows_bounded_operation_attributes() -> None: """Structured spans retain only allow-listed bounded operation attributes.""" - logger = _RecordingLogger() + recorder = _RecordingLogger() + logger = LoggerHandle(recorder) tracer = StructuredLogTracer(logger=logger) with tracer.start_span( @@ -75,12 +87,13 @@ def test_structured_log_tracer_allows_bounded_operation_attributes() -> None: }, ), ] - assert logger.events == expected_events, logger.events + assert recorder.events == expected_events, recorder.events def test_structured_log_metrics_emits_latency_and_value_events() -> None: """Structured metrics retain their event names and payload fields.""" - logger = _RecordingLogger() + recorder = _RecordingLogger() + logger = LoggerHandle(recorder) metrics = StructuredLogMetrics(logger=logger) labels = {"operation": "generation_run.execute"} @@ -112,8 +125,8 @@ def test_structured_log_metrics_emits_latency_and_value_events() -> None: }, ) - assert logger.events == [expected_latency_event, expected_value_event], ( - logger.events + assert recorder.events == [expected_latency_event, expected_value_event], ( + recorder.events ) diff --git a/tests/test_worker_routing_contract.py b/tests/test_worker_routing_contract.py index 6c891f83..82a01c8c 100644 --- a/tests/test_worker_routing_contract.py +++ b/tests/test_worker_routing_contract.py @@ -5,6 +5,8 @@ import pytest +from episodic.logging import LoggerHandle, LogLevel + if typ.TYPE_CHECKING: from syrupy.assertion import SnapshotAssertion @@ -16,12 +18,30 @@ class _FakeWorkerLogger: infos: list[str] exceptions: list[str] - def info(self, message: str) -> None: + def info(self, message: str, **kwargs: object) -> None: + del kwargs self.infos += [message] - def exception(self, message: str) -> None: + def exception(self, message: str, **kwargs: object) -> None: + del kwargs self.exceptions += [message] + def log( + self, + level: int | LogLevel, + message: str, + /, + *, + exc_info: object | None = None, + stack_info: bool = False, + ) -> None: + """Record a fallback port emission by its level.""" + del exc_info, stack_info + if level == 20: + self.infos += [message] + else: + self.exceptions += [message] + def _runtime_environ() -> dict[str, str]: return { @@ -114,7 +134,7 @@ def test_create_celery_app_logs_task_route_materialisation( from episodic.worker import runtime as runtime_module logger = _FakeWorkerLogger(infos=[], exceptions=[]) - monkeypatch.setattr(runtime_module, "logger", logger) + monkeypatch.setattr(runtime_module, "logger", LoggerHandle(logger)) create_celery_app(load_runtime_config(_runtime_environ())) @@ -133,7 +153,7 @@ def test_create_celery_app_logs_task_route_validation_failures( from episodic.worker import runtime as runtime_module logger = _FakeWorkerLogger(infos=[], exceptions=[]) - monkeypatch.setattr(runtime_module, "logger", logger) + monkeypatch.setattr(runtime_module, "logger", LoggerHandle(logger)) with pytest.raises( TypeError,