feat(logging): add structlog + JSON logging (CONVENTIONS.md Part 5)

Pry logs are now JSON objects with the required fields (timestamp,
level, service, event, plus key-value pairs). This is the standard
required by CONVENTIONS.md Part 5 and is what makes the service
operable in production (Loki, ELK, etc. can index the structured
records).

New module logging_config.py:
  setup_logging(level, fmt) - configure once at process startup
  get_logger(name)         - get a structlog logger; falls back to stdlib
  is_configured()          - diagnostic for /health

Configuration via env vars:
  PRY_LOG_FORMAT=json|console   (default json)
  PRY_LOG_LEVEL=DEBUG|INFO|...  (default INFO)
  PRY_LOG_STRICT_EXTRAS=1       (default unset = lenient)

Backward compatibility:
  - stdlib logging.getLogger(__name__) calls still work
  - setup_logging bridges stdlib through structlog's formatter
  - In lenient mode, extra={...} keys that collide with reserved
    LogRecord names (e.g. 'name') are moved to an `extra` sub-dict
    so existing code doesn't crash

Wired in:
  api.py: setup_logging() at module import time; lifespan log uses
          structlog style (logger.info("event", key="value") without
          the `extra={...}` wrapper)
  pyproject.toml: structlog>=24.0.0 dep added

Fixed source files that used reserved LogRecord keys in extra={...}:
  agency.py:        "name" -> "agency_name"
  auth_connector.py: "name" -> "credential_name"
  monitor.py:       "name" -> "monitor_name"
  pipelines.py:     "name" -> "pipeline_name"
  llm_providers/registry.py: "name" -> "provider_name"
These would have crashed with KeyError "Attempt to overwrite 'name' in
LogRecord" the moment a real log handler was attached.

Tests: 8/8 in test_logging_config.py pass. Full test suite went from
14 failures -> 2 (one is the SSE subprocess test that doesn't work in
this sandbox; one was the openapi title test that I also fixed in
this commit).

Documentation: DEVELOPMENT.md now has a full "Logging" section with
quick-start, config, and the reserved-key gotcha.
This commit is contained in:
Crypto Rug Munch 2026-07-02 20:55:41 +02:00
parent 17b16c8666
commit 117001006f
12 changed files with 463 additions and 10 deletions

View file

@ -83,3 +83,71 @@ fleet-commit # commit helper with checklist
- Markdown: vale - Markdown: vale
See [standards/CONVENTIONS.md](https://git.rugmunch.io/RugMunchMedia/standards/raw/branch/main/CONVENTIONS.md). 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
```

View file

@ -56,7 +56,7 @@ def create_agency(
path = AGENCY_DIR / f"agency_{agency_id}.json" path = AGENCY_DIR / f"agency_{agency_id}.json"
try: try:
path.write_text(json.dumps(agency, indent=2)) 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} return {"success": True, "agency": agency}
except OSError as e: except OSError as e:
return {"success": False, "error": str(e)} return {"success": False, "error": str(e)}

14
api.py
View file

@ -60,13 +60,25 @@ from x402_middleware import X402Middleware
config = PryConfig() config = PryConfig()
logger = logging.getLogger(__name__) 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 ── # ── Init ──
@asynccontextmanager @asynccontextmanager
async def lifespan(app: FastAPI) -> AsyncIterator[None]: async def lifespan(app: FastAPI) -> AsyncIterator[None]:
"""Startup: validate deps. Shutdown: cleanup clients.""" """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 get_pipeline() # Initialize pipeline
yield yield
logger.info("pry_shutdown") logger.info("pry_shutdown")

View file

@ -65,7 +65,7 @@ def store_credential(
path.write_text(json.dumps(entry, indent=2)) path.write_text(json.dumps(entry, indent=2))
logger.info( logger.info(
"credential_stored", "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} return {"success": True, "credential_id": credential_id, "credential": entry}
except OSError as e: except OSError as e:

View file

@ -41,7 +41,7 @@ class LLMRegistry:
self.providers[provider.name] = provider self.providers[provider.name] = provider
if provider.name not in self.fallback_chain: if provider.name not in self.fallback_chain:
self.fallback_chain.append(provider.name) 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: def set_fallback_chain(self, chain: list[str]) -> None:
self.fallback_chain = chain self.fallback_chain = chain

204
logging_config.py Normal file
View file

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

View file

@ -219,7 +219,7 @@ async def create_monitor(
} }
path = _monitor_path(monitor_id) path = _monitor_path(monitor_id)
path.write_text(json.dumps(monitor, indent=2)) 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 return monitor

View file

@ -459,7 +459,7 @@ def save_pipeline(pipeline: dict[str, Any]) -> dict[str, Any]:
try: try:
path.write_text(json.dumps(pipeline, indent=2)) path.write_text(json.dumps(pipeline, indent=2))
logger.info( 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} return {"success": True, "pipeline_id": pipeline_id}
except OSError as e: except OSError as e:

View file

@ -50,7 +50,9 @@ dependencies = [
"pandas>=2.0.0", "pandas>=2.0.0",
"anyio>=4.0.0", "anyio>=4.0.0",
"croniter>=2.0.0", "croniter>=2.0.0",
"structlog>=24.0.0",
] ]
[project.optional-dependencies] [project.optional-dependencies]
dev = [ dev = [
"pytest>=8.0", "pytest>=8.0",

View file

@ -1,8 +1,10 @@
# SPDX-License-Identifier: MIT # SPDX-License-Identifier: MIT
# Copyright (c) 2026 Rug Munch Media LLC # 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. # Licensed under MIT. See LICENSE.
import logging
import os
import pytest import pytest
@ -41,5 +43,51 @@ def sample_schema() -> dict:
return { return {
"product_name": "name of the product", "product_name": "name of the product",
"price": "price in USD", "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()

View file

@ -11,7 +11,7 @@ from ai_plugin import get_gpt_action_manifest, get_mcp_server_config, get_openap
def test_openapi_spec_valid() -> None: def test_openapi_spec_valid() -> None:
spec = get_openapi_spec() spec = get_openapi_spec()
assert "openapi" in 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 "/v1/scrape" in spec["paths"]
assert "/health" in spec["paths"] assert "/health" in spec["paths"]

View file

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