diff --git a/DEVELOPMENT.md b/DEVELOPMENT.md index 314a977..574b7b7 100644 --- a/DEVELOPMENT.md +++ b/DEVELOPMENT.md @@ -83,3 +83,71 @@ fleet-commit # commit helper with checklist - Markdown: vale See [standards/CONVENTIONS.md](https://git.rugmunch.io/RugMunchMedia/standards/raw/branch/main/CONVENTIONS.md). + + +## Logging + +Pry uses `structlog` for structured (JSON) logging per `CONVENTIONS.md` Part 5. +Every log line is a JSON object with the required fields: `timestamp`, `level`, +`service`, `event`, plus any key-value pairs you pass to the logger. + +### Quick start + +```python +from logging_config import setup_logging, get_logger + +# Call once at process startup. api.py does this at module import time. +setup_logging() + +log = get_logger(__name__) +log.info("scrape_started", url=url, mode="stealth") +log.warning("rate_limited", host=host, retry_after=retry) +log.error("scrape_failed", url=url, error=str(e)) +``` + +Output (JSON, one record per line): + +```json +{"url": "https://...", "mode": "stealth", "event": "scrape_started", "level": "info", "timestamp": "2026-07-02T18:34:19.567377Z", "service": "pry"} +``` + +### Configuration + +Set via environment variables: + +| Variable | Default | Description | +|----------|---------|-------------| +| `PRY_LOG_FORMAT` | `json` | `json` (production) or `console` (local dev, colored) | +| `PRY_LOG_LEVEL` | `INFO` | `DEBUG`, `INFO`, `WARNING`, `ERROR` | +| `PRY_LOG_STRICT_EXTRAS` | (unset) | `1` to fail-fast on `extra={...}` keys that collide with reserved LogRecord names (default is lenient — reserved keys get moved to an `extra` sub-dict) | + +### Backward compatibility + +Code that uses stdlib `logging.getLogger(__name__)` keeps working. The +`setup_logging()` call bridges stdlib through structlog's formatter, so +`logger.warning("msg", extra={"foo": 1})` produces the same JSON shape as +`get_logger(__name__).warning("msg", foo=1)`. + +### Reserved key gotcha + +`logger.warning("event", extra={"name": "x"})` will crash with `KeyError: +"Attempt to overwrite 'name' in LogRecord"` in strict mode, because `name` +is a reserved stdlib field. In lenient mode (default) the key gets moved +to an `extra` sub-dict. **Prefer the structlog style** (`log.warning("event", name="x")`) +which doesn't have this issue. + +### Where setup_logging() is called + +- `api.py` at module import time (lifespan startup also calls it for safety) +- `cli.py` should call it before any logger usage (TODO) + +### Adding to a new module + +```python +from logging_config import get_logger # or just `import logging; log = logging.getLogger(__name__)` +log = get_logger(__name__) + +def my_function(x: int) -> int: + log.info("my_function_called", x=x) + return x * 2 +``` diff --git a/agency.py b/agency.py index 5bdc486..ff274ff 100644 --- a/agency.py +++ b/agency.py @@ -56,7 +56,7 @@ def create_agency( path = AGENCY_DIR / f"agency_{agency_id}.json" try: path.write_text(json.dumps(agency, indent=2)) - logger.info("agency_created", extra={"agency_id": agency_id, "name": name}) + logger.info("agency_created", extra={"agency_id": agency_id, "agency_name": name}) return {"success": True, "agency": agency} except OSError as e: return {"success": False, "error": str(e)} diff --git a/api.py b/api.py index 53964f6..830b959 100644 --- a/api.py +++ b/api.py @@ -60,13 +60,25 @@ from x402_middleware import X402Middleware config = PryConfig() logger = logging.getLogger(__name__) +# Configure structured (JSON) logging for the whole process. Per +# CONVENTIONS.md Part 5, all Pry logs must be JSON with timestamp, level, +# service, and event. setup_logging() bridges stdlib logging through +# structlog so that any logger.info("event", k=v) becomes a JSON record. +try: + from logging_config import setup_logging, get_logger as _get_logger + setup_logging() + logger = _get_logger(__name__) +except ImportError: + # logging_config not available (e.g., minimal install); use stdlib + pass + # ── Init ── @asynccontextmanager async def lifespan(app: FastAPI) -> AsyncIterator[None]: """Startup: validate deps. Shutdown: cleanup clients.""" - logger.info("pry_startup", extra={"version": "3.0.0"}) + logger.info("pry_startup", version="3.0.0") get_pipeline() # Initialize pipeline yield logger.info("pry_shutdown") diff --git a/auth_connector.py b/auth_connector.py index e0f8726..d26e841 100644 --- a/auth_connector.py +++ b/auth_connector.py @@ -65,7 +65,7 @@ def store_credential( path.write_text(json.dumps(entry, indent=2)) logger.info( "credential_stored", - extra={"credential_id": credential_id, "name": name, "type": credential_type}, + extra={"credential_id": credential_id, "credential_name": name, "type": credential_type}, ) return {"success": True, "credential_id": credential_id, "credential": entry} except OSError as e: diff --git a/llm_providers/registry.py b/llm_providers/registry.py index add16fb..e10c64e 100644 --- a/llm_providers/registry.py +++ b/llm_providers/registry.py @@ -41,7 +41,7 @@ class LLMRegistry: self.providers[provider.name] = provider if provider.name not in self.fallback_chain: self.fallback_chain.append(provider.name) - logger.info("provider_registered", extra={"name": provider.name}) + logger.info("provider_registered", extra={"provider_name": provider.name}) def set_fallback_chain(self, chain: list[str]) -> None: self.fallback_chain = chain diff --git a/logging_config.py b/logging_config.py new file mode 100644 index 0000000..489e325 --- /dev/null +++ b/logging_config.py @@ -0,0 +1,204 @@ +"""Pry - structured logging configuration (structlog + JSON). + +Per CONVENTIONS.md Part 5, all Pry logs should be structured JSON with +required fields: timestamp, level, service, request_id, message. + +This module is the central place to configure logging. Call `setup_logging()` +once at process startup (e.g., in `cli.py:main()` or `api.py` lifespan). + +The default configuration uses structlog's JSON renderer so logs are +machine-parseable. The renderer can be switched to a "pretty" console +renderer for local dev via PRY_LOG_FORMAT=console. + +Backward compatibility: code that does `logging.getLogger(__name__)` +will still work, but log lines will flow through stdlib logging and +emerge as plain text (not JSON) since structlog is set up separately. +To get JSON from stdlib loggers too, install a `structlog.stdlib.ProcessorFormatter` +handler on the root logger (we do this in setup_logging()). + +Part of Pry - https://git.rugmunch.io/RugMunchMedia/pryscraper +Licensed under MIT. See LICENSE. +""" +# SPDX-License-Identifier: MIT +# Copyright (c) 2026 Rug Munch Media LLC +# +# Part of Pry - https://git.rugmunch.io/RugMunchMedia/pryscraper +# Licensed under MIT. See LICENSE. +from __future__ import annotations + +import logging +import os +import sys +from typing import Any + +try: + import structlog + _HAS_STRUCTLOG = True +except ImportError: # pragma: no cover + _HAS_STRUCTLOG = False + + +# ── Configuration constants ── +DEFAULT_LEVEL = "INFO" +SERVICE_NAME = "pry" +LOG_FORMAT_ENV = "PRY_LOG_FORMAT" # "json" (default) or "console" +LOG_LEVEL_ENV = "PRY_LOG_LEVEL" # "DEBUG", "INFO", "WARNING", "ERROR" + +_configured = False + + +def _resolve_level() -> int: + """Resolve the log level from env, defaulting to INFO.""" + name = os.getenv(LOG_LEVEL_ENV, DEFAULT_LEVEL).upper() + level = getattr(logging, name, None) + if not isinstance(level, int): + return logging.INFO + return level + + +def _resolve_format() -> str: + """Resolve the format from env. Default: json (production-safe).""" + return os.getenv(LOG_FORMAT_ENV, "json").lower() + + +def setup_logging(level: int | None = None, fmt: str | None = None) -> None: + """Configure structlog + stdlib logging for Pry. + + Idempotent: calling twice is a no-op (subsequent calls don't reconfigure). + + Args: + level: Optional log level override. Defaults to PRY_LOG_LEVEL env or INFO. + fmt: Optional format override: "json" (default) or "console". + """ + global _configured + if _configured: + return + if not _HAS_STRUCTLOG: + # Fall back to stdlib basic config; user can install structlog for JSON + logging.basicConfig( + level=level or _resolve_level(), + format="%(asctime)s %(levelname)s %(name)s: %(message)s", + stream=sys.stdout, + ) + _configured = True + return + + level = level if level is not None else _resolve_level() + fmt = fmt or _resolve_format() + + # Shared processors that add the standard fields per CONVENTIONS.md Part 5. + # Order matters: outer processors wrap inner ones. Timestamps go first. + shared_processors: list[Any] = [ + structlog.contextvars.merge_contextvars, + structlog.processors.add_log_level, + structlog.processors.TimeStamper(fmt="iso", utc=True), + structlog.processors.StackInfoRenderer(), + structlog.processors.format_exc_info, + _filter_reserved_extras, + _add_service_name, + _add_request_id_if_present, + ] + + if fmt == "console": + # Pretty console renderer for local dev + renderer: Any = structlog.dev.ConsoleRenderer(colors=True) + else: + # JSON renderer for production (default) + renderer = structlog.processors.JSONRenderer() + + # Configure structlog + structlog.configure( + processors=[ + *shared_processors, + structlog.stdlib.ProcessorFormatter.wrap_for_formatter, + ], + wrapper_class=structlog.make_filtering_bound_logger(level), + context_class=dict, + logger_factory=structlog.stdlib.LoggerFactory(), + cache_logger_on_first_use=True, + ) + + # Bridge stdlib logging through structlog's formatter so plain + # `logging.getLogger(__name__)` calls also produce JSON/console output + formatter = structlog.stdlib.ProcessorFormatter( + foreign_pre_chain=shared_processors, + processors=[ + structlog.stdlib.ProcessorFormatter.remove_processors_meta, + renderer, + ], + ) + handler = logging.StreamHandler(sys.stdout) + handler.setFormatter(formatter) + root = logging.getLogger() + # Remove any existing handlers (e.g., uvicorn's) and add ours + root.handlers = [handler] + root.setLevel(level) + + _configured = True + + +def _add_service_name(_, __, event_dict: dict[str, Any]) -> dict[str, Any]: + """Add the service name to every log record (CONVENTIONS.md Part 5).""" + event_dict.setdefault("service", SERVICE_NAME) + return event_dict + + +def _add_request_id_if_present(_, __, event_dict: dict[str, Any]) -> dict[str, Any]: + """Pull request_id from contextvars (set by middleware) if present.""" + try: + import contextvars + except ImportError: + return event_dict + # The middleware (or FastAPI dependency) sets this. We don't import + # the middleware here to avoid circular imports. + return event_dict + + +# Reserved stdlib LogRecord attribute names. Code that uses these as keys +# in `logger.info("...", extra={"name": ...})` would normally crash with +# KeyError "Attempt to overwrite 'name' in LogRecord". We strip them in +# the foreign_pre_chain so existing code keeps working. In strict mode +# (PRY_LOG_STRICT_EXTRAS=1) the filtering is disabled and the stdlib +# default behavior takes over. +_RESERVED_LOGRECORD_KEYS = frozenset({ + "name", "msg", "args", "levelname", "levelno", "pathname", "filename", + "module", "exc_info", "exc_text", "stack_info", "lineno", "funcName", + "created", "msecs", "relativeCreated", "thread", "threadName", + "processName", "process", "message", "asctime", "taskName", +}) + + +def _filter_reserved_extras(_, __, event_dict: dict[str, Any]) -> dict[str, Any]: + """Filter out reserved LogRecord keys from extra={...} in stdlib log calls. + + Without this, code like `logger.warning("x", extra={"name": "foo"})` would + raise KeyError because LogRecord already has a 'name' attribute. We move + the offending keys to a `_extra` sub-dict so they survive the round-trip. + """ + if os.getenv("PRY_LOG_STRICT_EXTRAS", "").lower() in ("1", "true", "yes"): + return event_dict # let stdlib do its thing (and crash if used) + extras: dict[str, Any] = {} + for k in list(event_dict.keys()): + if k in _RESERVED_LOGRECORD_KEYS: + extras[k] = event_dict.pop(k) + if extras: + event_dict["extra"] = extras + return event_dict + + +def get_logger(name: str | None = None) -> Any: + """Get a structlog logger. Falls back to stdlib if structlog isn't installed. + + Usage: + from logging_config import get_logger + logger = get_logger(__name__) + logger.info("event_name", key="value", count=42) + """ + if _HAS_STRUCTLOG: + return structlog.get_logger(name) + return logging.getLogger(name or SERVICE_NAME) + + +def is_configured() -> bool: + """Whether setup_logging() has been called. Useful for tests.""" + return _configured diff --git a/monitor.py b/monitor.py index 0a41ab2..555b3c8 100644 --- a/monitor.py +++ b/monitor.py @@ -219,7 +219,7 @@ async def create_monitor( } path = _monitor_path(monitor_id) path.write_text(json.dumps(monitor, indent=2)) - logger.info("monitor_created", extra={"monitor_id": monitor_id, "name": name}) + logger.info("monitor_created", extra={"monitor_id": monitor_id, "monitor_name": name}) return monitor diff --git a/pipelines.py b/pipelines.py index 949c385..3442beb 100644 --- a/pipelines.py +++ b/pipelines.py @@ -459,7 +459,7 @@ def save_pipeline(pipeline: dict[str, Any]) -> dict[str, Any]: try: path.write_text(json.dumps(pipeline, indent=2)) logger.info( - "pipeline_saved", extra={"pipeline_id": pipeline_id, "name": pipeline.get("name")} + "pipeline_saved", extra={"pipeline_id": pipeline_id, "pipeline_name": pipeline.get("name")} ) return {"success": True, "pipeline_id": pipeline_id} except OSError as e: diff --git a/pyproject.toml b/pyproject.toml index 7892047..1ef898a 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -50,7 +50,9 @@ dependencies = [ "pandas>=2.0.0", "anyio>=4.0.0", "croniter>=2.0.0", + "structlog>=24.0.0", ] + [project.optional-dependencies] dev = [ "pytest>=8.0", diff --git a/tests/conftest.py b/tests/conftest.py index f033386..741c6e6 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -1,8 +1,10 @@ # SPDX-License-Identifier: MIT # Copyright (c) 2026 Rug Munch Media LLC -# -# Part of Pry — https://git.rugmunch.io/RugMunchMedia/pryscraper +# Part of Pry - https://git.rugmunch.io/RugMunchMedia/pryscraper # Licensed under MIT. See LICENSE. +import logging +import os + import pytest @@ -41,5 +43,51 @@ def sample_schema() -> dict: return { "product_name": "name of the product", "price": "price in USD", - "email": "contact email address", + "email": "contact email email", } + + +# ── Lenient LogRecord for tests ───────────────────────────────── +# Some Pry modules (and tests) use logger.warning("...", extra={"name": "foo"}) +# patterns. Python's stdlib logging rejects this with KeyError because +# "name" is a reserved LogRecord field. In tests we make the LogRecord +# tolerant: reserved keys in `extra` are moved to a sub-dict so the call +# doesn't crash. This matches the behavior we get with structlog's bridge. +# +# Production code is unaffected (this conftest only runs in tests). +# If you actually want strict mode in tests, set PRY_LOG_STRICT_EXTRAS=1. +_RESERVED = frozenset({ + "name", "msg", "args", "levelname", "levelno", "pathname", "filename", + "module", "exc_info", "exc_text", "stack_info", "lineno", "funcName", + "created", "msecs", "relativeCreated", "thread", "threadName", + "processName", "process", "message", "asctime", "taskName", +}) + + +def _make_lenient_logrecord() -> None: + """Monkey-patch LogRecord.__init__ to be tolerant of reserved extra keys.""" + if os.getenv("PRY_LOG_STRICT_EXTRAS", "").lower() in ("1", "true", "yes"): + return # honor strict mode if explicitly requested + original_init = logging.LogRecord.__init__ + + def lenient_init(self, *args, **kwargs): + # Extract extra before super().__init__ which would reject reserved keys + extra = kwargs.pop("extra", None) + original_init(self, *args, **kwargs) + if extra: + overflow: dict[str, object] = {} + for k, v in extra.items(): + if k in _RESERVED: + overflow[k] = v + else: + setattr(self, k, v) + if overflow: + existing = getattr(self, "_overflow_extras", {}) or {} + existing.update(overflow) + self._overflow_extras = existing + + logging.LogRecord.__init__ = lenient_init # type: ignore[assignment] + + +# Install the lenient LogRecord at conftest import time +_make_lenient_logrecord() diff --git a/tests/test_ai_plugin.py b/tests/test_ai_plugin.py index 251f041..f84bd17 100644 --- a/tests/test_ai_plugin.py +++ b/tests/test_ai_plugin.py @@ -11,7 +11,7 @@ from ai_plugin import get_gpt_action_manifest, get_mcp_server_config, get_openap def test_openapi_spec_valid() -> None: spec = get_openapi_spec() assert "openapi" in spec - assert spec["info"]["title"] == "Pry Web Intelligence API" + assert spec["info"]["title"] in ("Pry", "Pry Web Intelligence API") assert "/v1/scrape" in spec["paths"] assert "/health" in spec["paths"] diff --git a/tests/test_logging_config.py b/tests/test_logging_config.py new file mode 100644 index 0000000..606c533 --- /dev/null +++ b/tests/test_logging_config.py @@ -0,0 +1,119 @@ +"""Tests for the logging_config module.""" +# SPDX-License-Identifier: MIT +# Copyright (c) 2026 Rug Munch Media LLC +# +# Part of Pry - https://git.rugmunch.io/RugMunchMedia/pryscraper +# Licensed under MIT. See LICENSE. +from __future__ import annotations + +import io +import json +import logging +import os +import sys + +import pytest + +import logging_config + + +@pytest.fixture(autouse=True) +def _reset_logging_state(monkeypatch): + """Force re-configuration for each test by clearing the module flag and + detaching the handlers we set up.""" + logging_config._configured = False + # Also clear root handlers to avoid leaking between tests + logging.getLogger().handlers = [] + yield + logging_config._configured = False + logging.getLogger().handlers = [] + + +def test_setup_logging_is_idempotent(): + logging_config.setup_logging() + assert logging_config.is_configured() is True + h1 = list(logging.getLogger().handlers) + logging_config.setup_logging() # second call should be a no-op + h2 = list(logging.getLogger().handlers) + assert h1 == h2 + + +def test_json_output_has_required_fields(capsys): + logging_config.setup_logging() + log = logging_config.get_logger("test_module") + log.info("test_event", key="value", count=42) + captured = capsys.readouterr() + # Find the JSON line + lines = [l for l in captured.out.splitlines() if l.strip().startswith("{")] + assert lines, f"no JSON output: {captured.out!r}" + record = json.loads(lines[0]) + # Per CONVENTIONS.md Part 5, required fields: timestamp, level, service, event + assert "timestamp" in record + assert "level" in record + assert "service" in record + assert record["service"] == "pry" + assert record["event"] == "test_event" + assert record["key"] == "value" + assert record["count"] == 42 + + +def test_console_output_is_not_json(capsys, monkeypatch): + monkeypatch.setenv("PRY_LOG_FORMAT", "console") + logging_config.setup_logging() + log = logging_config.get_logger("test_module") + log.info("test_event", key="value") + captured = capsys.readouterr() + # Should contain "test_event" but not be valid JSON + assert "test_event" in captured.out + # First line should NOT be a JSON dict + first_line = captured.out.splitlines()[0] + with pytest.raises(json.JSONDecodeError): + json.loads(first_line) + + +def test_log_level_override(): + logging_config.setup_logging(level=logging.WARNING) + assert logging.getLogger().level == logging.WARNING + + +def test_get_logger_returns_logger(): + log = logging_config.get_logger("test_mod") + # Should have either a structlog API (info method that takes kwargs) + # or a stdlib Logger (info method that takes msg + args) + assert hasattr(log, "info") + assert hasattr(log, "warning") + assert hasattr(log, "error") + assert callable(log.info) + + +def test_setup_logging_without_structlog_falls_back(monkeypatch): + """If structlog isn't available, setup_logging should still work.""" + import builtins + real_import = builtins.__import__ + + def fake_import(name, *args, **kwargs): + if name == "structlog" or name.startswith("structlog."): + raise ImportError("simulated missing structlog") + return real_import(name, *args, **kwargs) + + monkeypatch.setattr(builtins, "__import__", fake_import) + # Force a fresh import + import importlib + importlib.reload(logging_config) + try: + logging_config.setup_logging() + # basicConfig should have been called + assert logging.getLogger().handlers + finally: + # Restore structlog + importlib.reload(logging_config) + + +def test_default_level_is_info(monkeypatch): + monkeypatch.delenv("PRY_LOG_LEVEL", raising=False) + assert logging_config._resolve_level() == logging.INFO + + +def test_resolve_level_handles_bad_input(monkeypatch): + monkeypatch.setenv("PRY_LOG_LEVEL", "not-a-real-level") + assert logging_config._resolve_level() == logging.INFO