diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index 907e2cf2..40c113c3 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -6,22 +6,36 @@ usually save everyone time. ## Dev setup -```bash -git clone https://github.com/plind-junior/vouch +\`\`\`bash +git clone https://github.com/vouchdev/vouch cd vouch python -m venv .venv && source .venv/bin/activate pip install -e '.[dev]' -``` +\`\`\` ## Day-to-day -```bash +\`\`\`bash make test # pytest make lint # ruff check make format # ruff format make type # mypy make check # lint + type + test -``` +\`\`\` + +## Environment variables + +| Variable | Values | Default | Purpose | +|---|---|---|---| +| `VOUCH_LOG_FORMAT` | `text` or `json` | `text` | Log output format. `json` emits one JSON object per line with `time`, `level`, `logger`, `message`, and any `extra=` fields merged in at the top level. | +| `VOUCH_LOG_LEVEL` | Any standard level name | `WARNING` | Root logger level. Set to `DEBUG` for verbose output during development. | +| `VOUCH_LOG_FILE` | Filesystem path | unset | Append logs to this file in addition to stderr. Honoured for both `text` and `json` formats. | + +Example for local debugging: + +\`\`\`bash +VOUCH_LOG_FORMAT=json VOUCH_LOG_LEVEL=DEBUG vouch status +\`\`\` ## Sending a PR @@ -29,15 +43,35 @@ make check # lint + type + test `kb.*` method surface, the on-disk layout, the bundle format, or the audit-log shape. These are load-bearing for downstream tools and reviewed users — they need a [VEP](proposals/README.md), not just a PR. -2. Branch from `main`. Keep PRs focused; one concern per PR. +2. Branch from `main`. Target `test` for feature branches — `test` is the + integration branch and reaches `main` via release branches. Keep PRs + focused; one concern per PR. 3. Add or update tests. New CLI subcommands need a test in `tests/`; schema changes need a round-trip test in `tests/test_storage.py` or - `tests/test_bundle.py`. + `tests/test_bundle.py`; new env-var behaviour needs a test in + `tests/test_logging_config.py`. 4. Run `make check` locally before pushing. 5. Update `CHANGELOG.md` under `## [Unreleased]`. 6. PR description should answer: *what changed, why, and what would break for someone with an existing `.vouch/` directory?* +## Logging guidelines + +- Call `configure_logging()` once at process startup (CLI entry point, MCP + server, JSONL server). Do not call it inside library code. +- Use `logging.getLogger(__name__)` in every module — never the root logger + directly. +- Pass structured context via `extra=` rather than string interpolation when + `VOUCH_LOG_FORMAT=json` consumers may parse the output: + +\`\`\`python +logger.info("proposal approved", extra={"proposal_id": pid, "actor": actor}) +\`\`\` + +- vouch uses `_VouchManagedHandler` (a `logging.StreamHandler` subclass) to + mark its own handlers. Host applications and test frameworks can add their + own handlers without risk of them being removed by `configure_logging()`. + ## Things we won't merge - Anything that bypasses the review gate from the agent side @@ -59,6 +93,8 @@ make check # lint + type + test to YAML. - No comments unless the *why* is non-obvious. Identifier names should carry the *what*. +- Use subclasses as markers in preference to sentinel attributes — it keeps + `isinstance` checks clean and avoids `type: ignore[attr-defined]`. ## Reporting bugs / asking for features diff --git a/src/vouch/logging_config.py b/src/vouch/logging_config.py index 33a61908..c37a0901 100644 --- a/src/vouch/logging_config.py +++ b/src/vouch/logging_config.py @@ -1,18 +1,33 @@ -"""Logging configuration honouring `VOUCH_LOG_FORMAT`. +"""Logging configuration honouring VOUCH_LOG_FORMAT. -When `VOUCH_LOG_FORMAT=json`, attach a JSON handler to the `vouch` logger +When VOUCH_LOG_FORMAT=json, attach a JSON handler to the vouch logger namespace so each log record is emitted as one JSON object per line with -`level`, `logger`, `event`, and any structured extras passed by callers -(notably `actor` and `object_ids`, to mirror the audit-log shape). - -Any other value (including unset) is a no-op: vouch's loggers keep the -stdlib default behaviour, so this module never changes log routing for -callers who don't opt in. - -Entry points (`cli.cli`, `server.run_stdio`, `jsonl_server.run_jsonl`) -call `configure_logging()` exactly once at startup. The implementation is -idempotent — repeated calls swap the formatter on the existing handler -rather than stacking new ones. +level, logger, time, event, and any structured extras passed by callers +(notably actor and object_ids, to mirror the audit-log shape). + +Any other value (including unset) is a no-op: vouch loggers keep stdlib +default behaviour, so this module never changes log routing for callers +who have not opted in. + +Entry points (cli.cli, server.run_stdio, jsonl_server.run_jsonl) call +configure_logging() exactly once at startup. The implementation is +idempotent — repeated calls replace the existing handler rather than +stacking new ones. + +Environment variables honoured: + + VOUCH_LOG_FORMAT "text" (default) or "json" + VOUCH_LOG_LEVEL Any standard level name (default: WARNING). + Applied to the vouch logger namespace. + VOUCH_LOG_FILE Optional filesystem path. When set, logs are also + appended to this file in addition to stderr. + Honoured for both text and json formats. + A bad path (e.g. read-only FS) is caught and a + warning is emitted to stderr instead of crashing. + +Sensitive field redaction: top-level extra= keys whose names contain +"secret", "token", "password", or "key" are replaced with "***REDACTED***" +in JSON output so credentials are never written to log sinks. """ from __future__ import annotations @@ -21,13 +36,15 @@ import logging import os import sys -from typing import Any +from typing import Any, NamedTuple VOUCH_LOGGER_NAME = "vouch" ENV_VAR = "VOUCH_LOG_FORMAT" +ENV_LEVEL = "VOUCH_LOG_LEVEL" +ENV_FILE = "VOUCH_LOG_FILE" + +_SENSITIVE_SUBSTRINGS = frozenset({"secret", "token", "password", "key"}) -# stdlib LogRecord attributes — anything else on a record was attached via -# `logger.info(..., extra={"actor": ...})` and should land in JSON output. _STDLIB_RECORD_FIELDS = frozenset({ "name", "msg", "args", "levelname", "levelno", "pathname", "filename", "module", "exc_info", "exc_text", "stack_info", "lineno", "funcName", @@ -36,34 +53,36 @@ }) -class _VouchManagedHandler(logging.StreamHandler): - """Marker subclass for the handler `configure_logging()` owns. +def _is_sensitive(key: str) -> bool: + """Return True if key name suggests a sensitive value.""" + lower = key.lower() + return any(sub in lower for sub in _SENSITIVE_SUBSTRINGS) + + +class _VouchManagedHandler(logging.StreamHandler): # type: ignore[type-arg] + """Marker subclass for handlers configure_logging() owns. Identifying our handler by type (rather than tagging a plain - `StreamHandler` with an attribute) keeps the install/reuse/remove logic - readable and avoids an `attr-defined` ignore. + StreamHandler with an attribute) keeps install/reuse/remove logic + readable and avoids an attr-defined ignore. """ class JsonFormatter(logging.Formatter): """Emit each log record as one JSON object per line. - Always includes `level`, `logger`, and `event` (the formatted message, - overridable via `extra={"event": "..."}`). Structured extras attached - via the stdlib `extra=` parameter are merged into the same object. + Always includes level, logger, time, and event (the formatted message, + overridable via extra={"event": "..."}). Structured extras attached via + the stdlib extra= parameter are merged into the same object. + + Sensitive fields (keys containing secret, token, password, or key) are + replaced with ***REDACTED*** so credentials never reach log sinks. """ def format(self, record: logging.LogRecord) -> str: - """Serialise `record` as one JSON object. - - `event` defaults to the formatted message but may be overridden by - the caller passing `extra={"event": "..."}`. All non-stdlib record - attributes are merged in alongside the required keys. When the - record carries `exc_info`, the formatted traceback is attached as - `exc`. - """ payload: dict[str, Any] = { "level": record.levelname, + "time": self.formatTime(record, "%Y-%m-%dT%H:%M:%S"), "logger": record.name, "event": ( record.__dict__["event"] @@ -74,58 +93,114 @@ def format(self, record: logging.LogRecord) -> str: for key, value in record.__dict__.items(): if key in _STDLIB_RECORD_FIELDS or key in payload: continue - payload[key] = value + payload[key] = "***REDACTED***" if _is_sensitive(key) else value if record.exc_info: payload["exc"] = self.formatException(record.exc_info) return json.dumps(payload, default=str, sort_keys=True) -def _selected_format() -> str: - """Return `"json"` iff `VOUCH_LOG_FORMAT` env var is `json`, else `"text"`. +class LoggingConfig(NamedTuple): + """Result of configure_logging() — effective format, level, and file path.""" + format: str + level: int + log_file: str | None - The comparison is case- and whitespace-insensitive; any other value - (including unset, empty, or `text`) maps to `"text"` so callers who - have not opted in see no behaviour change. - """ + +def _selected_format() -> str: + """Return "json" iff VOUCH_LOG_FORMAT env var is "json", else "text".""" raw = os.environ.get(ENV_VAR, "").strip().lower() return "json" if raw == "json" else "text" -def configure_logging() -> str: - """Install or remove the JSON handler based on `VOUCH_LOG_FORMAT`. - - In `json` mode: attaches a stderr `StreamHandler` with `JsonFormatter` - to the `vouch` logger and sets `propagate=False` so vouch's records do - not double-emit through the root handler. In `text` mode: removes any - handler this function previously installed and restores `propagate`, - leaving the `vouch` logger in its stdlib default state. - - Safe to call from every entry point: handlers installed by a prior - call are detected by their `_VouchManagedHandler` type and reused - rather than stacked, so the function is idempotent across repeat - invocations and across format switches (e.g. text -> json -> text in - tests). - - Returns the selected format name (`"json"` or `"text"`). +def _open_log_file(path: str) -> _VouchManagedHandler | None: + """Open a file handler for path, returning None and warning on OSError.""" + try: + return _VouchManagedHandler(open(path, "a", encoding="utf-8")) + except OSError as exc: + print( + f"vouch: warning: could not open VOUCH_LOG_FILE {path!r}: {exc}", + file=sys.stderr, + ) + return None + + +def configure_logging(*, force: bool = False) -> LoggingConfig: + """Install or update the vouch log handler based on environment variables. + + In json mode: attaches a stderr _VouchManagedHandler with JsonFormatter + to the vouch logger and sets propagate=False so vouch records do not + double-emit through the root handler. In text mode (the default): vouch + loggers propagate to the root handler as normal — no managed handler is + added unless VOUCH_LOG_FILE is set, in which case a file handler is + installed so file output works without requiring json mode. + + If VOUCH_LOG_FILE is set, a _VouchManagedHandler writing to that file is + also installed. A bad path emits a warning to stderr and is skipped rather + than crashing the server. + + Safe to call from every entry point: handlers installed by a prior call + are detected by _VouchManagedHandler type and replaced rather than + stacked, so the function is idempotent. Pass force=True to force + reconfiguration even if handlers are already installed (useful in tests). + + Returns a LoggingConfig named tuple reflecting the *effective* installed + state: format and level are always read fresh from env; log_file reflects + whether a file handler was successfully opened. """ selected = _selected_format() + level_name = os.environ.get(ENV_LEVEL, "WARNING").upper() + level = getattr(logging, level_name, logging.WARNING) + log_file = os.environ.get(ENV_FILE, "").strip() or None + logger = logging.getLogger(VOUCH_LOGGER_NAME) - existing: _VouchManagedHandler | None = next( - (h for h in logger.handlers if isinstance(h, _VouchManagedHandler)), - None, - ) + existing: list[_VouchManagedHandler] = [ + h for h in logger.handlers if isinstance(h, _VouchManagedHandler) + ] + if existing and not force: + # Return the *effective* config by inspecting what is installed. + installed_format = "json" if any( + isinstance(h.formatter, JsonFormatter) for h in existing + ) else "text" + installed_file = next( + (getattr(h.stream, "name", None) for h in existing + if h.stream is not sys.stderr), + None, + ) + return LoggingConfig(format=installed_format, level=logger.level, log_file=installed_file) + + for h in existing: + logger.removeHandler(h) + h.close() + + def _make_formatter() -> logging.Formatter: + if selected == "json": + return JsonFormatter() + return logging.Formatter("%(asctime)s %(levelname)-8s %(name)s: %(message)s") + + effective_log_file: str | None = None if selected == "json": - if existing is None: - handler = _VouchManagedHandler(sys.stderr) - logger.addHandler(handler) - else: - handler = existing - handler.setFormatter(JsonFormatter()) + stderr_handler = _VouchManagedHandler(sys.stderr) + stderr_handler.setFormatter(_make_formatter()) + logger.addHandler(stderr_handler) + if log_file: + fh = _open_log_file(log_file) + if fh is not None: + fh.setFormatter(_make_formatter()) + logger.addHandler(fh) + effective_log_file = log_file logger.propagate = False - elif existing is not None: - logger.removeHandler(existing) + else: + # Text mode is a true no-op for the vouch logger unless VOUCH_LOG_FILE + # is set — propagate=True lets the root handler do its job as before. + if log_file: + fh = _open_log_file(log_file) + if fh is not None: + fh.setFormatter(_make_formatter()) + logger.addHandler(fh) + effective_log_file = log_file logger.propagate = True - return selected + logger.setLevel(level) + return LoggingConfig(format=selected, level=level, log_file=effective_log_file) diff --git a/tests/test_logging.py b/tests/test_logging.py index 75bfb38a..a0f86dd2 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -95,7 +95,7 @@ def test_json_formatter_includes_exception_when_present(): def test_configure_logging_no_env_var_is_noop(): selected = configure_logging() - assert selected == "text" + assert selected.format == "text" logger = logging.getLogger(VOUCH_LOGGER_NAME) assert not any(isinstance(h, _VouchManagedHandler) for h in logger.handlers) assert logger.propagate is True @@ -105,7 +105,7 @@ def test_configure_logging_no_env_var_is_noop(): def test_configure_logging_explicit_text_values_are_noop(monkeypatch, value): monkeypatch.setenv("VOUCH_LOG_FORMAT", value) selected = configure_logging() - assert selected == "text" + assert selected.format == "text" logger = logging.getLogger(VOUCH_LOGGER_NAME) assert not any(isinstance(h, _VouchManagedHandler) for h in logger.handlers) assert logger.propagate is True @@ -114,7 +114,7 @@ def test_configure_logging_explicit_text_values_are_noop(monkeypatch, value): def test_configure_logging_json_installs_handler(monkeypatch): monkeypatch.setenv("VOUCH_LOG_FORMAT", "json") selected = configure_logging() - assert selected == "json" + assert selected.format == "json" logger = logging.getLogger(VOUCH_LOGGER_NAME) managed = [h for h in logger.handlers if isinstance(h, _VouchManagedHandler)] assert len(managed) == 1 @@ -134,10 +134,10 @@ def test_configure_logging_is_idempotent(monkeypatch): def test_configure_logging_switches_back_to_text(monkeypatch): monkeypatch.setenv("VOUCH_LOG_FORMAT", "json") - configure_logging() + configure_logging(force=True) monkeypatch.delenv("VOUCH_LOG_FORMAT", raising=False) - selected = configure_logging() - assert selected == "text" + selected = configure_logging(force=True) + assert selected.format == "text" logger = logging.getLogger(VOUCH_LOGGER_NAME) assert not any(isinstance(h, _VouchManagedHandler) for h in logger.handlers) @@ -165,13 +165,12 @@ def test_json_handler_emits_one_object_per_line(monkeypatch): lines = [ln for ln in buf.getvalue().splitlines() if ln.strip()] assert len(lines) == 2 first = json.loads(lines[0]) - assert first == { - "actor": "alice", - "event": "session.crystallize", - "level": "INFO", - "logger": "vouch.sessions", - "object_ids": ["sess-1", "claim-2"], - } + assert first["actor"] == "alice" + assert first["event"] == "session.crystallize" + assert first["level"] == "INFO" + assert first["logger"] == "vouch.sessions" + assert first["object_ids"] == ["sess-1", "claim-2"] + assert "time" in first second = json.loads(lines[1]) assert second["level"] == "WARNING" assert second["event"] == "proposal.approve_failed" diff --git a/tests/test_logging_config.py b/tests/test_logging_config.py new file mode 100644 index 00000000..dd478d09 --- /dev/null +++ b/tests/test_logging_config.py @@ -0,0 +1,154 @@ +"""Tests for vouch logging configuration.""" +from __future__ import annotations + +import json +import logging + + +def _reconfigure(monkeypatch, fmt=None, level=None, log_file=None, force=True): + """Helper: set env vars and force-reconfigure logging.""" + if fmt is None: + monkeypatch.delenv("VOUCH_LOG_FORMAT", raising=False) + else: + monkeypatch.setenv("VOUCH_LOG_FORMAT", fmt) + if level is None: + monkeypatch.delenv("VOUCH_LOG_LEVEL", raising=False) + else: + monkeypatch.setenv("VOUCH_LOG_LEVEL", level) + if log_file is None: + monkeypatch.delenv("VOUCH_LOG_FILE", raising=False) + else: + monkeypatch.setenv("VOUCH_LOG_FILE", log_file) + import importlib + + import vouch.logging_config as lc + importlib.reload(lc) + return lc.configure_logging(force=force) + + +def test_json_format_emits_valid_json(monkeypatch): + monkeypatch.setenv("VOUCH_LOG_FORMAT", "json") + from vouch.logging_config import JsonFormatter + formatter = JsonFormatter() + record = logging.LogRecord( + name="vouch.test", level=logging.WARNING, + pathname="", lineno=0, msg="test message", + args=(), exc_info=None, + ) + line = formatter.format(record) + obj = json.loads(line) + assert obj["level"] == "WARNING" + assert obj["event"] == "test message" + assert "time" in obj + assert "logger" in obj + + +def test_text_format_is_default(monkeypatch): + cfg = _reconfigure(monkeypatch, fmt=None) + assert cfg.format == "text" + + +def test_json_extra_fields_are_merged(monkeypatch): + """Extra fields passed via extra= should appear in JSON output.""" + from vouch.logging_config import JsonFormatter + formatter = JsonFormatter() + record = logging.LogRecord( + name="vouch.test", level=logging.INFO, + pathname="", lineno=0, msg="event", + args=(), exc_info=None, + ) + record.__dict__["proposal_id"] = "abc-123" + record.__dict__["actor"] = "user@example.com" + line = formatter.format(record) + obj = json.loads(line) + assert obj["proposal_id"] == "abc-123" + assert obj["actor"] == "user@example.com" + + +def test_event_key_overridable(monkeypatch): + """Caller can override the event field via extra={"event": "..."}.""" + from vouch.logging_config import JsonFormatter + formatter = JsonFormatter() + record = logging.LogRecord( + name="vouch.test", level=logging.INFO, + pathname="", lineno=0, msg="raw message", + args=(), exc_info=None, + ) + record.__dict__["event"] = "custom.event.name" + line = formatter.format(record) + obj = json.loads(line) + assert obj["event"] == "custom.event.name" + + +def test_sensitive_fields_are_redacted(monkeypatch): + """Keys containing secret/token/password/key should be redacted in JSON.""" + from vouch.logging_config import JsonFormatter + formatter = JsonFormatter() + record = logging.LogRecord( + name="vouch.test", level=logging.INFO, + pathname="", lineno=0, msg="auth attempt", + args=(), exc_info=None, + ) + record.__dict__["api_token"] = "supersecret123" + record.__dict__["password"] = "hunter2" + record.__dict__["actor"] = "alice" + line = formatter.format(record) + obj = json.loads(line) + assert obj["api_token"] == "***REDACTED***" + assert obj["password"] == "***REDACTED***" + assert obj["actor"] == "alice" + + +def test_vouch_log_level_is_honoured(monkeypatch): + """VOUCH_LOG_LEVEL should set the vouch logger level.""" + cfg = _reconfigure(monkeypatch, fmt="json", level="DEBUG") + logger = logging.getLogger("vouch") + assert logger.level == logging.DEBUG + assert cfg.level == logging.DEBUG + + +def test_vouch_log_file_writes_to_file(monkeypatch, tmp_path): + """VOUCH_LOG_FILE should append log lines to the specified file.""" + log_path = tmp_path / "vouch.log" + _reconfigure(monkeypatch, fmt="json", level="DEBUG", log_file=str(log_path)) + logger = logging.getLogger("vouch.test_file") + logger.setLevel(logging.DEBUG) + logger.warning("file test message") + content = log_path.read_text() + assert content.strip(), "Log file should not be empty" + obj = json.loads(content.strip().splitlines()[-1]) + assert obj["event"] == "file test message" + + +def test_managed_handler_replaced_on_force(monkeypatch): + """force=True should replace managed handlers, not stack them.""" + monkeypatch.delenv("VOUCH_LOG_FILE", raising=False) + _reconfigure(monkeypatch, fmt="json") + _reconfigure(monkeypatch, fmt="json") + import vouch.logging_config as lc + logger = logging.getLogger("vouch") + managed = [h for h in logger.handlers if isinstance(h, lc._VouchManagedHandler)] + assert len(managed) == 1 + + +def test_returns_logging_config_namedtuple(monkeypatch): + """configure_logging should return a LoggingConfig named tuple.""" + cfg = _reconfigure(monkeypatch, fmt="json", level="INFO") + assert cfg.format == "json" + assert cfg.level == logging.INFO + assert cfg.log_file is None + assert hasattr(cfg, "_fields") + + +def test_propagate_false_in_json_mode(monkeypatch): + """vouch logger should not propagate in json mode to avoid double-emit.""" + _reconfigure(monkeypatch, fmt="json") + logger = logging.getLogger("vouch") + assert logger.propagate is False + + +def test_propagate_true_in_text_mode(monkeypatch): + """vouch logger should propagate in text mode (stdlib default).""" + _reconfigure(monkeypatch, fmt="text") + logger = logging.getLogger("vouch") + assert logger.propagate is True