8a62f6b014
Adds an operational logging layer separate from the JSONL trace audit logs. Operational logs cover system events (startup, errors, MCP transport, research lifecycle); JSONL traces remain the researcher provenance audit trail. Backend: structlog with two renderers selectable via MARCHWARDEN_LOG_FORMAT (json|console). Defaults to console when stderr is a TTY, json otherwise — so dev runs are human-readable and shipped runs (containers, automation) emit OpenSearch-ready JSON without configuration. Key features: - Named loggers per component: marchwarden.cli, marchwarden.mcp, marchwarden.researcher.web - MARCHWARDEN_LOG_LEVEL controls global level (default INFO) - MARCHWARDEN_LOG_FILE=1 enables a 10MB-rotating file at ~/.marchwarden/logs/marchwarden.log - structlog contextvars bind trace_id + researcher at the start of each research() call so every downstream log line carries them automatically; cleared on completion - stdlib logging is funneled through the same pipeline so noisy third-party loggers (httpx, anthropic) get the same formatting and quieted to WARN unless DEBUG is requested - Logs to stderr to keep MCP stdio stdout clean Wired into: - cli.main.cli — configures logging on startup, logs ask_started/ ask_completed/ask_failed - researchers.web.server.main — configures logging on startup, logs mcp_server_starting - researchers.web.agent.research — binds trace context, logs research_started/research_completed Tests verify JSON and console formats, contextvar propagation, level filtering, idempotency, and auto-configure-on-first-use. 94/94 tests passing. Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>
128 lines
4 KiB
Python
128 lines
4 KiB
Python
"""Tests for the obs (structured logging) module."""
|
|
|
|
import io
|
|
import json
|
|
import logging
|
|
import os
|
|
from unittest.mock import patch
|
|
|
|
import pytest
|
|
import structlog
|
|
|
|
from obs import configure_logging, get_logger
|
|
|
|
|
|
@pytest.fixture(autouse=True)
|
|
def reset_logging():
|
|
"""Reset structlog + stdlib state between tests so configure_logging
|
|
is forced to re-run."""
|
|
import obs
|
|
|
|
obs._CONFIGURED = False
|
|
structlog.reset_defaults()
|
|
structlog.contextvars.clear_contextvars()
|
|
root = logging.getLogger()
|
|
root.handlers = []
|
|
root.setLevel(logging.WARNING)
|
|
yield
|
|
obs._CONFIGURED = False
|
|
structlog.reset_defaults()
|
|
structlog.contextvars.clear_contextvars()
|
|
root.handlers = []
|
|
|
|
|
|
def _capture_stderr(monkeypatch):
|
|
buf = io.StringIO()
|
|
monkeypatch.setattr("sys.stderr", buf)
|
|
return buf
|
|
|
|
|
|
class TestConfigureLogging:
|
|
def test_json_format_emits_json(self, monkeypatch):
|
|
monkeypatch.setenv("MARCHWARDEN_LOG_FORMAT", "json")
|
|
monkeypatch.setenv("MARCHWARDEN_LOG_LEVEL", "INFO")
|
|
buf = _capture_stderr(monkeypatch)
|
|
|
|
configure_logging(force=True)
|
|
log = get_logger("marchwarden.test")
|
|
log.info("hello", key="value", count=3)
|
|
|
|
line = buf.getvalue().strip()
|
|
assert line, "expected at least one log line"
|
|
parsed = json.loads(line)
|
|
assert parsed["event"] == "hello"
|
|
assert parsed["key"] == "value"
|
|
assert parsed["count"] == 3
|
|
assert parsed["level"] == "info"
|
|
assert parsed["logger"] == "marchwarden.test"
|
|
assert "timestamp" in parsed
|
|
|
|
def test_console_format_is_human_readable(self, monkeypatch):
|
|
monkeypatch.setenv("MARCHWARDEN_LOG_FORMAT", "console")
|
|
monkeypatch.setenv("MARCHWARDEN_LOG_LEVEL", "INFO")
|
|
buf = _capture_stderr(monkeypatch)
|
|
|
|
configure_logging(force=True)
|
|
log = get_logger("marchwarden.test")
|
|
log.info("greeting", who="world")
|
|
|
|
text = buf.getvalue()
|
|
assert "greeting" in text
|
|
assert "world" in text
|
|
# Console renderer is not JSON
|
|
with pytest.raises(json.JSONDecodeError):
|
|
json.loads(text.strip().splitlines()[-1])
|
|
|
|
def test_context_binding_propagates(self, monkeypatch):
|
|
monkeypatch.setenv("MARCHWARDEN_LOG_FORMAT", "json")
|
|
buf = _capture_stderr(monkeypatch)
|
|
|
|
configure_logging(force=True)
|
|
log = get_logger("marchwarden.test")
|
|
structlog.contextvars.bind_contextvars(trace_id="abc-123", researcher="web")
|
|
try:
|
|
log.info("step")
|
|
finally:
|
|
structlog.contextvars.clear_contextvars()
|
|
|
|
parsed = json.loads(buf.getvalue().strip())
|
|
assert parsed["trace_id"] == "abc-123"
|
|
assert parsed["researcher"] == "web"
|
|
|
|
def test_log_level_filters(self, monkeypatch):
|
|
monkeypatch.setenv("MARCHWARDEN_LOG_FORMAT", "json")
|
|
monkeypatch.setenv("MARCHWARDEN_LOG_LEVEL", "WARNING")
|
|
buf = _capture_stderr(monkeypatch)
|
|
|
|
configure_logging(force=True)
|
|
log = get_logger("marchwarden.test")
|
|
log.info("ignored")
|
|
log.warning("kept")
|
|
|
|
lines = [l for l in buf.getvalue().strip().splitlines() if l]
|
|
assert len(lines) == 1
|
|
assert json.loads(lines[0])["event"] == "kept"
|
|
|
|
def test_idempotent(self, monkeypatch):
|
|
monkeypatch.setenv("MARCHWARDEN_LOG_FORMAT", "json")
|
|
configure_logging(force=True)
|
|
|
|
import obs
|
|
|
|
obs._CONFIGURED = True
|
|
# Second call should be a no-op
|
|
before = logging.getLogger().handlers
|
|
configure_logging()
|
|
after = logging.getLogger().handlers
|
|
assert before is after
|
|
|
|
def test_get_logger_auto_configures(self, monkeypatch):
|
|
monkeypatch.setenv("MARCHWARDEN_LOG_FORMAT", "json")
|
|
buf = _capture_stderr(monkeypatch)
|
|
|
|
# No explicit configure_logging() call
|
|
log = get_logger("marchwarden.test")
|
|
log.info("auto")
|
|
|
|
parsed = json.loads(buf.getvalue().strip())
|
|
assert parsed["event"] == "auto"
|