diff --git a/CHANGELOG.md b/CHANGELOG.md index e445894..542752c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -29,6 +29,8 @@ and versions are tracked in the repo-root `VERSION` file. - Add the optional `base-cli[typer]` integration with `attach_typer()`, `TyperAdapter`, and `get_typer_command()` so Typer command trees can adopt the same lifecycle without making Typer a core dependency. +- Add opt-in versioned JSON success/error envelopes, redacted bounded JSON + logs, and public contract helpers for machine-facing integrations. ### Changed diff --git a/README.md b/README.md index e4d4f17..6d0fb52 100644 --- a/README.md +++ b/README.md @@ -37,6 +37,10 @@ Typer applications can opt into the same lifecycle with the optional for the migration path; Typer remains optional and is never imported by the core Click integration. +Automation-facing JSON output, errors, and logs are opt-in through the +versioned contracts documented in [`docs/json-contracts.md`](docs/json-contracts.md). +Human output and Click error behavior remain the default. + ## Design Goals CLI tools should be easy to write, but not magical. A command should be @@ -453,11 +457,14 @@ Every `base_cli.App` command gets these options: - `--keep-temp`: preserve the run's temp directory after command completion. - `--log-file `: write the persistent log to a specific file. - `--version`: shown when the `App` was created with a version. +- `--json`: opt-in machine output, when `LifecycleOptions.json` is enabled; + emits the versioned envelopes described in [`docs/json-contracts.md`](docs/json-contracts.md). `LifecycleOptions()` preserves this default set. Its `debug`, `quiet`, `environment`, `config`, `keep_temp`, `log_file`, and `version` fields are -enabled by default; `dry_run` is opt-in. Set one field to `None` to disable it, -or replace it with a `LifecycleOption` to rename and configure it independently: +enabled by default; `dry_run` and `json` are opt-in. Set one field to `None` to +disable it, or replace it with a `LifecycleOption` to rename and configure it +independently: ```python lifecycle_options = base_cli.LifecycleOptions( @@ -485,6 +492,14 @@ app = base_cli.App( ) ``` +For scripts, add the JSON option explicitly: + +```python +lifecycle_options = base_cli.LifecycleOptions( + json=base_cli.LifecycleOption("--json"), +) +``` + `LifecycleOption` accepts Click declarations followed by the keyword-only `name`, `help`, `metavar`, `envvar`, `show_envvar`, `show_default`, `hidden`, and `default` presentation and value-source settings. When `name` is omitted, @@ -528,7 +543,7 @@ def inspect(click_ctx: click.Context) -> None: values = base_cli.get_lifecycle_values(click_ctx) assert isinstance(values, base_cli.LifecycleValues) assert values is click_ctx.meta[base_cli.LIFECYCLE_META_KEY] - print(values.environment, values.debug, values.dry_run) + print(values.environment, values.debug, values.dry_run, values.json) ``` The metadata record, rather than `click.Context.obj`, carries values between a diff --git a/docs/json-contracts.md b/docs/json-contracts.md new file mode 100644 index 0000000..9af6a20 --- /dev/null +++ b/docs/json-contracts.md @@ -0,0 +1,73 @@ +# JSON contracts + +Machine-facing output is opt-in. Configure a JSON lifecycle option on an app +when a command is intended for scripts or automation: + +```python +import base_cli + +app = base_cli.App( + name="example", + lifecycle_options=base_cli.LifecycleOptions( + json=base_cli.LifecycleOption("--json"), + ), +) +``` + +`example --json` captures command stdout and emits exactly one success or error +envelope on stdout. Logs remain on stderr. Human mode, including the default +Click error rendering and command stdout behavior, is unchanged. + +## Output and errors + +Both envelopes use `schema_version: 1` and stable fields: + +```json +{ + "schema_version": 1, + "schema": "base-cli.output", + "code": "ok", + "type": "success", + "message": "Success", + "details": {"exit_code": 0, "stdout": "hello\n"}, + "run_id": "20260804T192202_dd231351" +} +``` + +Failures use `schema: "base-cli.error"`, `type: "error"`, and a deterministic +`code` derived from the lifecycle outcome (`usage_error`, `click_error`, +`aborted`, `interrupted`, `unexpected_error`, and so on). `details` always +contains the numeric `exit_code` and captured command stdout. A command's +human output is represented as a JSON string, so it cannot introduce prose or +ANSI escapes as a second stdout record. + +`run_id` is the lifecycle run identifier when startup reached a runtime +context, otherwise it is `null`. Unexpected failures intentionally expose only +the generic message `Unexpected internal error.`; diagnostics stay in logs. + +The lower-level `success_envelope()`, `error_envelope()`, `dumps_envelope()`, +and `redact_json_value()` helpers are public for commands that need to publish +their own structured `details` records. Secret-looking keys (`token`, +`password`, `secret`, `api_key`, and `authorization`) and credential-bearing +URLs are redacted recursively. + +## JSON logs + +Pass `json_logs=True` and the run identifier to `configure_logger()` when an +integration needs structured logs without enabling machine output: + +```python +logger = base_cli.configure_logger( + "example", + log_file, + debug=True, + json_logs=True, + run_id="run-123", +) +``` + +Each line is a JSON object with `schema_version`, `schema`, `timestamp` (UTC), +`level`, `logger`, `message`, and `run_id`. Messages are redacted and capped at +8 KiB; persistent files retain base-cli's owner-only permissions and JSON mode +bounds default-log retention to the most recent 20 files (or the explicit +`max_log_files` setting). JSON logs never use terminal color codes. diff --git a/lib/python/base_cli/__init__.py b/lib/python/base_cli/__init__.py index a5ddd4a..d380320 100644 --- a/lib/python/base_cli/__init__.py +++ b/lib/python/base_cli/__init__.py @@ -30,7 +30,7 @@ def _resolve_version() -> str: __version__ = _resolve_version() -from . import command_filters, command_protocol, history, testing +from . import command_filters, command_protocol, history, json_contracts, testing from .attachment import ( AttachmentAdapter, AttachmentContextFactory, @@ -74,6 +74,18 @@ def _resolve_version() -> str: from .errors import ConfigurationError from .exit_codes import ExitCode from .inspection import inspection_envelope, render_inspection_json +from .json_contracts import ( + JSON_CONTRACT_VERSION, + JSON_ERROR_SCHEMA, + JSON_LOG_SCHEMA, + JSON_OUTPUT_SCHEMA, + JsonLogFormatter, + MAX_JSON_LOG_MESSAGE_LENGTH, + dumps_envelope, + error_envelope, + redact_json_value, + success_envelope, +) from .logging import configure_logger, log_critical, log_debug, log_error, log_info, log_warning from .lifecycle_options import ( LIFECYCLE_META_KEY, @@ -144,8 +156,17 @@ def _resolve_version() -> str: "command_filters", "command_matches", "command_protocol", + "json_contracts", + "JSON_CONTRACT_VERSION", + "JSON_ERROR_SCHEMA", + "JSON_LOG_SCHEMA", + "JSON_OUTPUT_SCHEMA", + "JsonLogFormatter", + "MAX_JSON_LOG_MESSAGE_LENGTH", + "dumps_envelope", "dumps_record", "dumps_records", + "error_envelope", "history", "inspection_envelope", "render_inspection_json", @@ -181,8 +202,10 @@ def _resolve_version() -> str: "render_document", "render_records", "register_record_schema", + "redact_json_value", "resolve_output_format", "run_app", + "success_envelope", "RuntimeBinding", "ServicesT", "HistoryWriter", diff --git a/lib/python/base_cli/app.py b/lib/python/base_cli/app.py index 7142cef..5ca4f1e 100644 --- a/lib/python/base_cli/app.py +++ b/lib/python/base_cli/app.py @@ -1,6 +1,7 @@ from __future__ import annotations import functools +import io import inspect import logging import os @@ -10,6 +11,7 @@ import traceback from collections.abc import Iterable from contextvars import ContextVar, Token +from contextlib import redirect_stdout from dataclasses import dataclass from datetime import datetime from pathlib import Path @@ -37,6 +39,7 @@ from .exit_codes import ExitCode from .history import utc_now from .logging import configure_logger, log_invocation +from .json_contracts import dumps_envelope, error_envelope, success_envelope from .lifecycle_options import ( LIFECYCLE_META_KEY, LifecycleOption, @@ -57,8 +60,8 @@ redact_argv, ) -_STANDARD_OPTION_KEYS = ("debug", "quiet", "environment", "config", "keep_temp", "log_file") -_FLAG_LIFECYCLE_OPTION_KEYS = frozenset({"debug", "quiet", "keep_temp", "dry_run"}) +_STANDARD_OPTION_KEYS = ("debug", "quiet", "environment", "config", "keep_temp", "log_file", "json") +_FLAG_LIFECYCLE_OPTION_KEYS = frozenset({"debug", "quiet", "keep_temp", "dry_run", "json"}) _NATIVE_LIFECYCLE_OPTION_ORDER = ( "quiet", "debug", @@ -67,6 +70,7 @@ "keep_temp", "log_file", "dry_run", + "json", ) _ATTACHED_LIFECYCLE_OPTION_ORDER = ( "log_file", @@ -76,6 +80,7 @@ "debug", "quiet", "dry_run", + "json", ) _LIFECYCLE_CAPTURE_META_KEY = object() _LIFECYCLE_RESOLUTION_META_KEY = object() @@ -98,6 +103,7 @@ _CLICK_INSTRUMENTED_SENTINEL = object() _CLICK_MAIN_INSTRUMENTED_SENTINEL = object() _CLICK_ATTACHMENT_LOCK = RLock() +_JSON_DEFAULT_MAX_LOG_FILES = 20 _REGISTRATION_OPEN = "open" _REGISTRATION_MATERIALIZING = "materializing" _REGISTRATION_FROZEN = "frozen" @@ -121,6 +127,7 @@ class _InvocationState: debug_option: str | None = "--debug" options_parsed: bool = False attached_completion: bool = False + json_output: bool = False @dataclass(frozen=True) @@ -298,6 +305,7 @@ def _capture_standard_options(standard: dict[str, Any], owner_app: App) -> None: return state.debug = bool(standard.get("debug")) state.quiet = bool(standard.get("quiet")) + state.json_output = bool(standard.get("json")) state.options_parsed = True @@ -306,12 +314,14 @@ def _capture_effective_output_options( owner_app: App, debug: bool, quiet: bool, + json_output: bool = False, ) -> None: state = _INVOCATION_STATE.get() if state is None or state.owner_app is not owner_app: return state.debug = debug state.quiet = quiet + state.json_output = json_output def _record_unexpected_traceback(context: Context[Any, Any, Any], outcome: InvocationOutcome) -> None: @@ -1099,6 +1109,7 @@ def _create_context( owner_app=self, debug=debug, quiet=quiet, + json_output=bool(standard.get("json")), ) runtime = self.profile.resolve_runtime(self.name, project) @@ -1148,6 +1159,7 @@ def _create_context( dry_run=dry_run, history_scope=runtime.history_scope, history_parent_run_id=runtime.history_parent_run_id, + json_output=bool(standard.get("json")), ) context._run_metadata_path = run_metadata_path @@ -1173,13 +1185,23 @@ def _create_context( logger_activation_started = True try: - context.log = configure_logger(self.name, log_file, debug, quiet=quiet) + context.log = configure_logger( + self.name, + log_file, + debug, + quiet=quiet, + json_logs=context.json_output, + run_id=context.run_id, + ) except OSError as exc: target = f"persistent log file '{log_file}'" if log_file is not None else "stderr logging" raise RuntimeDirectoryError(f"Unable to configure {target}: {exc}") from exc context.log.debug("cli=%s run_id=%s environment=%s", self.name, run_id, environment) - if self.max_log_files is not None and uses_default_log_file and log_file is not None: - prune_log_files(layout.owner_root / "runs", log_file, self.max_log_files, context.log) + retention_limit = self.max_log_files + if retention_limit is None and context.json_output: + retention_limit = _JSON_DEFAULT_MAX_LOG_FILES + if retention_limit is not None and uses_default_log_file and log_file is not None: + prune_log_files(layout.owner_root / "runs", log_file, retention_limit, context.log) if runtime.write_identity and selected_project_root is not None and not dry_run and self.log_to_file: try: @@ -1913,6 +1935,7 @@ def raw_value(key: str) -> Any: keep_temp=bool(raw_value("keep_temp")), log_file=paths["log_file"], dry_run=bool(raw_value("dry_run")), + json=bool(raw_value("json")), ) @@ -2748,8 +2771,10 @@ def run_app( debug_option=_primary_lifecycle_declaration( app.lifecycle_options.debug, ), + json_output=_json_requested(args, app.lifecycle_options), ) state_token = _INVOCATION_STATE.set(state) + output_capture: io.StringIO | None = None try: try: display_command = app.profile.display_command() @@ -2758,18 +2783,30 @@ def run_app( invocation_token = _INVOCATION_ARGV.set(invocation_argv) try: bypass_token = _INVOCATION_MAIN_BYPASS.set(command) + output_capture = io.StringIO() if state.json_output else None try: - result = command.main( - args=args, - prog_name=display_command or app.name, - standalone_mode=False, - ) + if output_capture is None: + result = command.main( + args=args, + prog_name=display_command or app.name, + standalone_mode=False, + ) + else: + with redirect_stdout(output_capture): + result = command.main( + args=args, + prog_name=display_command or app.name, + standalone_mode=False, + ) finally: _reset_context_var(_INVOCATION_MAIN_BYPASS, bypass_token) finally: _reset_context_var(_INVOCATION_ARGV, invocation_token) except click.Abort as exc: outcome = outcome_from_exception(click, exc) + if state.json_output: + _emit_json_error(state, outcome, str(exc), output_capture) + return outcome.exit_code if outcome.kind == "interrupted": print("Interrupted.", file=sys.stderr) else: @@ -2777,6 +2814,11 @@ def run_app( return outcome.exit_code except click.ClickException as exc: outcome = outcome_from_exception(click, exc) + if state.json_output: + if reraise_unexpected: + raise + _emit_json_error(state, outcome, exc.format_message(), output_capture) + return outcome.exit_code if outcome.kind == "unexpected_error": if reraise_unexpected: raise @@ -2785,29 +2827,132 @@ def run_app( exc.show() return outcome.exit_code except KeyboardInterrupt: + if state.json_output: + outcome = outcome_from_exception(click, KeyboardInterrupt()) + _emit_json_error(state, outcome, "Interrupted.", output_capture) + return outcome.exit_code print("Interrupted.", file=sys.stderr) return ExitCode.INTERRUPTED except SystemExit as exc: + if state.json_output: + outcome = outcome_from_exception(click, exc) + detail = str(exc.code) if exc.code is not None and not isinstance(exc.code, int) else "" + _emit_json_error(state, outcome, detail or "Command exited.", output_capture) + return outcome.exit_code if exc.code is not None and not isinstance(exc.code, int): print(str(exc.code), file=sys.stderr) return system_exit_code(exc) except Exception as exc: if reraise_unexpected: raise + if state.json_output: + outcome = outcome_from_exception(click, exc) + _emit_json_error(state, outcome, "Unexpected internal error.", output_capture) + return outcome.exit_code _show_unexpected_error(state, exc) return ExitCode.FAILURE try: if state.attached_completion: + if state.json_output: + _emit_json_success(state, ExitCode.SUCCESS, output_capture) return ExitCode.SUCCESS - return _normalize_command_result(result) + exit_code = _normalize_command_result(result) + if state.json_output: + if exit_code == ExitCode.SUCCESS: + _emit_json_success(state, exit_code, output_capture) + else: + _emit_json_error( + state, + outcome_from_exit_code(exit_code), + "Command returned a non-zero exit code.", + output_capture, + ) + return exit_code except TypeError as exc: + if state.json_output: + outcome = outcome_from_exception(click, exc) + _emit_json_error(state, outcome, str(exc), output_capture) + return outcome.exit_code print(f"ERROR: {exc}", file=sys.stderr) return ExitCode.FAILURE finally: + if output_capture is not None and not state.json_output: + sys.stdout.write(output_capture.getvalue()) _reset_context_var(_INVOCATION_STATE, state_token) +def _json_requested(args: list[str], lifecycle_options: LifecycleOptions) -> bool: + option = lifecycle_options.json + if option is None: + return False + if option.default is True: + return True + if option.envvar is not None: + envvars = (option.envvar,) if isinstance(option.envvar, str) else option.envvar + if any(os.environ.get(name, "").lower() in {"1", "true", "yes", "on"} for name in envvars): + return True + declarations = tuple( + declaration + for declaration in option.param_decls + if declaration.startswith(("-", "/")) + ) + return any( + argument == declaration or argument.startswith(f"{declaration}=") + for argument in args + for declaration in declarations + ) + + +def _captured_stdout(output_capture: io.StringIO | None) -> str: + return "" if output_capture is None else output_capture.getvalue() + + +def _emit_json_success( + state: _InvocationState, + exit_code: int, + output_capture: io.StringIO | None, +) -> None: + details = { + "exit_code": exit_code, + "stdout": _captured_stdout(output_capture), + } + sys.stdout.write( + dumps_envelope( + success_envelope( + run_id=state.run_id, + details=details, + message="Success" if exit_code == ExitCode.SUCCESS else "Command completed with a non-zero exit code.", + code="ok" if exit_code == ExitCode.SUCCESS else "nonzero_return", + ) + ) + ) + + +def _emit_json_error( + state: _InvocationState, + outcome: InvocationOutcome, + message: str, + output_capture: io.StringIO | None, +) -> None: + if outcome.exit_code == ExitCode.SUCCESS: + _emit_json_success(state, outcome.exit_code, output_capture) + return + sys.stdout.write( + dumps_envelope( + error_envelope( + run_id=state.run_id, + code=outcome.kind, + message=message, + details={ + "exit_code": outcome.exit_code, + "stdout": _captured_stdout(output_capture), + }, + ) + ) + ) + + def _show_unexpected_error(state: _InvocationState, exc: Exception) -> None: print("Error: Unexpected internal error.", file=sys.stderr) if state.run_id is not None: diff --git a/lib/python/base_cli/context.py b/lib/python/base_cli/context.py index f840127..8bcc9f7 100644 --- a/lib/python/base_cli/context.py +++ b/lib/python/base_cli/context.py @@ -72,6 +72,7 @@ class Context(Generic[ConfigT, ApplicationStateT, ServicesT]): services: ServicesT | None = field(default=None, repr=False, compare=False) framework_config: FrameworkConfig | None = field(default=None, repr=False, compare=False) config_provenance: Mapping[str, str] = field(default_factory=dict, repr=False, compare=False) + json_output: bool = False _run_metadata_path: Path | None = field(default=None, init=False, repr=False, compare=False) _owns_temp_dir: bool = field(default=False, init=False, repr=False, compare=False) _owned_temp_identity: tuple[int, int] | None = field(default=None, init=False, repr=False, compare=False) diff --git a/lib/python/base_cli/json_contracts.py b/lib/python/base_cli/json_contracts.py new file mode 100644 index 0000000..79a851b --- /dev/null +++ b/lib/python/base_cli/json_contracts.py @@ -0,0 +1,156 @@ +"""Versioned JSON contracts for machine-facing CLI consumers. + +The helpers in this module deliberately return plain dictionaries so a +consumer can extend ``details`` without depending on a framework-specific +model class. Field names and their meanings are part of the public v1 +contract and are documented in ``docs/json-contracts.md``. +""" + +from __future__ import annotations + +import json +import logging +import re +from datetime import datetime, timezone +from logging import LogRecord +from typing import Any, Mapping + +from .redaction import REDACTED, redact_text_value + + +JSON_CONTRACT_VERSION = 1 +JSON_LOG_SCHEMA = "base-cli.log" +JSON_OUTPUT_SCHEMA = "base-cli.output" +JSON_ERROR_SCHEMA = "base-cli.error" +MAX_JSON_LOG_MESSAGE_LENGTH = 8192 + +_SENSITIVE_ASSIGNMENT = re.compile( + r"(?i)(\b(?:token|password|secret|api[-_]?key|authorization)\b\s*[:=]\s*)" + r"([^\s,;]+)" +) + +__all__ = [ + "JSON_CONTRACT_VERSION", + "JSON_ERROR_SCHEMA", + "JSON_LOG_SCHEMA", + "JSON_OUTPUT_SCHEMA", + "JsonLogFormatter", + "MAX_JSON_LOG_MESSAGE_LENGTH", + "error_envelope", + "success_envelope", + "dumps_envelope", + "redact_json_value", +] + + +def success_envelope( + *, + run_id: str | None, + details: Mapping[str, Any] | None = None, + message: str = "Success", + code: str = "ok", +) -> dict[str, Any]: + """Return the stable v1 machine-readable success envelope.""" + + return { + "schema_version": JSON_CONTRACT_VERSION, + "schema": JSON_OUTPUT_SCHEMA, + "code": code, + "type": "success", + "message": _safe_text(message), + "details": redact_json_value(dict(details or {})), + "run_id": run_id, + } + + +def error_envelope( + *, + run_id: str | None, + code: str, + message: str, + details: Mapping[str, Any] | None = None, +) -> dict[str, Any]: + """Return the stable v1 machine-readable error envelope.""" + + return { + "schema_version": JSON_CONTRACT_VERSION, + "schema": JSON_ERROR_SCHEMA, + "code": _safe_text(code), + "type": "error", + "message": _safe_text(message), + "details": redact_json_value(dict(details or {})), + "run_id": run_id, + } + + +def dumps_envelope(envelope: Mapping[str, Any]) -> str: + """Serialize an envelope as one compact, newline-terminated JSON record.""" + + return json.dumps( + redact_json_value(dict(envelope)), + ensure_ascii=False, + separators=(",", ":"), + ) + "\n" + + +def redact_json_value(value: Any, *, _key: str | None = None) -> Any: + """Recursively redact secret-looking JSON keys and text values.""" + + if _key is not None and _is_sensitive_key(_key): + return REDACTED + if isinstance(value, Mapping): + return { + str(key): redact_json_value(item, _key=str(key)) + for key, item in value.items() + } + if isinstance(value, list): + return [redact_json_value(item) for item in value] + if isinstance(value, tuple): + return [redact_json_value(item) for item in value] + if isinstance(value, str): + return _safe_text(value) + return value + + +class JsonLogFormatter(logging.Formatter): + """Format one ``LogRecord`` as a bounded, redacted JSON object.""" + + def __init__(self, run_id: str | None = None) -> None: + super().__init__() + self.run_id = run_id + + def format(self, record: LogRecord) -> str: + message = _safe_text(record.getMessage()) + if len(message) > MAX_JSON_LOG_MESSAGE_LENGTH: + message = message[:MAX_JSON_LOG_MESSAGE_LENGTH] + "…" + payload: dict[str, Any] = { + "schema_version": JSON_CONTRACT_VERSION, + "schema": JSON_LOG_SCHEMA, + "timestamp": _timestamp(record.created), + "level": record.levelname, + "logger": record.name, + "message": message, + "run_id": self.run_id, + } + if record.exc_info: + payload["details"] = { + "exception_type": record.exc_info[0].__name__, + } + return json.dumps(payload, ensure_ascii=False, separators=(",", ":")) + + +def _timestamp(value: float) -> str: + return ( + datetime.fromtimestamp(value, tz=timezone.utc) + .isoformat(timespec="milliseconds") + .replace("+00:00", "Z") + ) + + +def _safe_text(value: str) -> str: + redacted = redact_text_value(value) + return _SENSITIVE_ASSIGNMENT.sub(r"\1" + REDACTED, redacted) + + +def _is_sensitive_key(value: str) -> bool: + return re.search(r"(?i)(token|password|secret|api[-_]?key|authorization)", value) is not None diff --git a/lib/python/base_cli/lifecycle_options.py b/lib/python/base_cli/lifecycle_options.py index 79fde42..1f0febc 100644 --- a/lib/python/base_cli/lifecycle_options.py +++ b/lib/python/base_cli/lifecycle_options.py @@ -160,6 +160,7 @@ class LifecycleOptions: log_file: LifecycleOption | None = field(default_factory=_log_file_option) version: LifecycleOption | None = field(default_factory=_version_option) dry_run: LifecycleOption | None = None + json: LifecycleOption | None = None def __post_init__(self) -> None: for key in ( @@ -171,6 +172,7 @@ def __post_init__(self) -> None: "log_file", "version", "dry_run", + "json", ): value = getattr(self, key) if value is not None and not isinstance(value, LifecycleOption): @@ -190,6 +192,7 @@ class LifecycleValues: keep_temp: bool = False log_file: Path | None = None dry_run: bool = False + json: bool = False def get_lifecycle_values(click_context: Any | None = None) -> LifecycleValues: diff --git a/lib/python/base_cli/logging.py b/lib/python/base_cli/logging.py index f0ccefa..bd8b34f 100644 --- a/lib/python/base_cli/logging.py +++ b/lib/python/base_cli/logging.py @@ -10,6 +10,7 @@ from ._private_files import restrict_file from .context import get_current_context +from .json_contracts import JsonLogFormatter from .paths import current_working_dir from .redaction import redact_argv @@ -32,6 +33,8 @@ def configure_logger( quiet: bool = False, stream: TextIO | None = None, formatter: logging.Formatter | None = None, + json_logs: bool = False, + run_id: str | None = None, ) -> logging.Logger: logger = logging.getLogger(f"base_cli.{cli_name}") logger.setLevel(logging.DEBUG) @@ -43,13 +46,27 @@ def configure_logger( user_stream = stream if stream is not None else sys.stderr user_handler = logging.StreamHandler(user_stream) user_handler.setLevel(_user_stream_level(debug, quiet)) - user_handler.setFormatter(_handler_formatter(formatter, use_color=_use_color(user_stream))) + user_handler.setFormatter( + _handler_formatter( + formatter, + use_color=_use_color(user_stream), + json_logs=json_logs, + run_id=run_id, + ) + ) logger.addHandler(user_handler) if log_file is not None: file_handler = SecureLogFileHandler(log_file, encoding="utf-8") file_handler.setLevel(logging.DEBUG) - file_handler.setFormatter(_handler_formatter(formatter, use_color=False)) + file_handler.setFormatter( + _handler_formatter( + formatter, + use_color=False, + json_logs=json_logs, + run_id=run_id, + ) + ) logger.addHandler(file_handler) return logger @@ -62,9 +79,17 @@ def _user_stream_level(debug: bool, quiet: bool) -> int: return logging.INFO -def _handler_formatter(formatter: logging.Formatter | None, *, use_color: bool) -> logging.Formatter: +def _handler_formatter( + formatter: logging.Formatter | None, + *, + use_color: bool, + json_logs: bool, + run_id: str | None, +) -> logging.Formatter: if formatter is not None: return formatter + if json_logs: + return JsonLogFormatter(run_id) return CliFormatter(use_color=use_color) diff --git a/tests/test_json_contracts.py b/tests/test_json_contracts.py new file mode 100644 index 0000000..712de65 --- /dev/null +++ b/tests/test_json_contracts.py @@ -0,0 +1,208 @@ +from __future__ import annotations + +import importlib.util +import io +import json +import os +import tempfile +import unittest +from pathlib import Path + +import base_cli +from base_cli.json_contracts import MAX_JSON_LOG_MESSAGE_LENGTH + + +@unittest.skipUnless(importlib.util.find_spec("click"), "Click is not installed") +class JsonContractTests(unittest.TestCase): + def _lifecycle_options(self) -> base_cli.LifecycleOptions: + return base_cli.LifecycleOptions( + json=base_cli.LifecycleOption("--json"), + ) + + def test_envelopes_have_stable_fields_and_recursive_redaction(self) -> None: + success = base_cli.success_envelope( + run_id="run-1", + details={"token": "secret", "nested": [{"password": "hidden"}]}, + ) + failure = base_cli.error_envelope( + run_id="run-1", + code="usage_error", + message="authorization=secret", + details={"api_key": "hidden"}, + ) + + self.assertEqual( + set(success), + {"schema_version", "schema", "code", "type", "message", "details", "run_id"}, + ) + self.assertEqual(success["schema_version"], 1) + self.assertEqual(success["schema"], "base-cli.output") + self.assertEqual(success["details"]["token"], "[REDACTED]") + self.assertEqual(success["details"]["nested"][0]["password"], "[REDACTED]") + self.assertEqual(failure["schema"], "base-cli.error") + self.assertEqual(failure["message"], "authorization=[REDACTED]") + self.assertEqual(json.loads(base_cli.dumps_envelope(failure)), failure) + + def test_json_log_formatter_is_bounded_redacted_and_color_free(self) -> None: + stream = io.StringIO() + logger = base_cli.configure_logger( + "json-formatter", + None, + debug=True, + stream=stream, + json_logs=True, + run_id="run-2", + ) + logger.info("token=secret %s", "x" * (MAX_JSON_LOG_MESSAGE_LENGTH + 20)) + + payload = json.loads(stream.getvalue()) + self.assertEqual(payload["schema_version"], 1) + self.assertEqual(payload["schema"], "base-cli.log") + self.assertEqual(payload["run_id"], "run-2") + self.assertEqual(payload["level"], "INFO") + self.assertIn("token=[REDACTED]", payload["message"]) + self.assertLessEqual(len(payload["message"]), MAX_JSON_LOG_MESSAGE_LENGTH + 1) + self.assertNotIn("\033[", stream.getvalue()) + + def test_json_success_captures_stdout_and_keeps_logs_on_stderr(self) -> None: + app = base_cli.App( + name="json-success", + log_to_file=False, + lifecycle_options=self._lifecycle_options(), + ) + observed: list[bool] = [] + + @app.command() + def main(ctx: base_cli.Context) -> None: + observed.append(base_cli.get_lifecycle_values().json) + ctx.log.info("token=secret") + print("hello") + + with tempfile.TemporaryDirectory() as home: + result = base_cli.testing.invoke(app, ["--json"], home=Path(home)) + + self.assertEqual(result.exit_code, 0, result.output) + envelope = json.loads(result.stdout) + self.assertEqual(envelope["schema"], "base-cli.output") + self.assertEqual(envelope["code"], "ok") + self.assertEqual(envelope["details"]["stdout"], "hello\n") + self.assertEqual(observed, [True]) + log_lines = [json.loads(line) for line in result.stderr.splitlines() if line] + self.assertTrue(log_lines) + self.assertTrue(all(line["schema"] == "base-cli.log" for line in log_lines)) + self.assertTrue(all("[REDACTED]" in line["message"] or "token" not in line["message"] for line in log_lines)) + + def test_json_error_is_machine_only_and_exit_code_is_deterministic(self) -> None: + import click + + app = base_cli.App( + name="json-error", + log_to_file=False, + lifecycle_options=self._lifecycle_options(), + ) + + @app.command() + def main(ctx: base_cli.Context) -> None: + del ctx + print("partial") + raise click.UsageError("password=secret") + + with tempfile.TemporaryDirectory() as home: + result = base_cli.testing.invoke(app, ["--json"], home=Path(home)) + + self.assertEqual(result.exit_code, 2) + envelope = json.loads(result.stdout) + self.assertEqual(envelope["schema"], "base-cli.error") + self.assertEqual(envelope["code"], "usage_error") + self.assertEqual(envelope["details"]["exit_code"], 2) + self.assertEqual(envelope["details"]["stdout"], "partial\n") + self.assertEqual(envelope["message"], "password=[REDACTED]") + self.assertEqual(result.stderr, "") + + def test_json_nonzero_command_return_is_an_error_envelope(self) -> None: + app = base_cli.App( + name="json-nonzero", + log_to_file=False, + lifecycle_options=self._lifecycle_options(), + ) + + @app.command() + def main(ctx: base_cli.Context) -> int: + del ctx + print("partial") + return 7 + + with tempfile.TemporaryDirectory() as home: + result = base_cli.testing.invoke(app, ["--json"], home=Path(home)) + + self.assertEqual(result.exit_code, 7) + envelope = json.loads(result.stdout) + self.assertEqual(envelope["type"], "error") + self.assertEqual(envelope["code"], "nonzero_return") + self.assertEqual(envelope["details"]["exit_code"], 7) + + def test_json_help_exit_is_a_success_envelope(self) -> None: + app = base_cli.App( + name="json-help", + log_to_file=False, + lifecycle_options=self._lifecycle_options(), + ) + + @app.command() + def main(ctx: base_cli.Context) -> None: + del ctx + + with tempfile.TemporaryDirectory() as home: + result = base_cli.testing.invoke(app, ["--json", "--help"], home=Path(home)) + + self.assertEqual(result.exit_code, 0) + envelope = json.loads(result.stdout) + self.assertEqual(envelope["type"], "success") + self.assertIn("Usage:", envelope["details"]["stdout"]) + + def test_json_envvar_opt_in_also_captures_command_output(self) -> None: + app = base_cli.App( + name="json-envvar", + log_to_file=False, + lifecycle_options=base_cli.LifecycleOptions( + json=base_cli.LifecycleOption("--json", envvar="BASE_JSON_MODE"), + ), + ) + + @app.command() + def main(ctx: base_cli.Context) -> None: + del ctx + print("hello from env") + + with tempfile.TemporaryDirectory() as home: + old_value = os.environ.get("BASE_JSON_MODE") + os.environ["BASE_JSON_MODE"] = "1" + try: + result = base_cli.testing.invoke(app, [], home=Path(home)) + finally: + if old_value is None: + os.environ.pop("BASE_JSON_MODE", None) + else: + os.environ["BASE_JSON_MODE"] = old_value + + envelope = json.loads(result.stdout) + self.assertEqual(envelope["type"], "success") + self.assertEqual(envelope["details"]["stdout"], "hello from env\n") + + def test_json_mode_is_opt_in_and_human_output_remains_unchanged(self) -> None: + app = base_cli.App(name="human-default", log_to_file=False) + + @app.command() + def main(ctx: base_cli.Context) -> None: + del ctx + print("hello") + + with tempfile.TemporaryDirectory() as home: + result = base_cli.testing.invoke(app, [], home=Path(home)) + + self.assertEqual(result.exit_code, 0, result.output) + self.assertEqual(result.stdout, "hello\n") + + +if __name__ == "__main__": + unittest.main() diff --git a/tests/test_public_api.py b/tests/test_public_api.py index bd9176d..70c7053 100644 --- a/tests/test_public_api.py +++ b/tests/test_public_api.py @@ -6,7 +6,16 @@ from unittest import mock import base_cli -from base_cli import attachment, command_filters, command_protocol, config, history, lifecycle_options, typer +from base_cli import ( + attachment, + command_filters, + command_protocol, + config, + history, + json_contracts, + lifecycle_options, + typer, +) class PublicApiTests(unittest.TestCase): @@ -41,6 +50,9 @@ def test_facade_exports_supported_modules_functions_and_types(self) -> None: "TyperAdapter", "attach_typer", "get_typer_command", + "JSON_CONTRACT_VERSION", + "success_envelope", + "error_envelope", "ConfigSnapshot", "RuntimeLayout", "attach", @@ -66,6 +78,7 @@ def test_facade_exports_supported_modules_functions_and_types(self) -> None: self.assertIs(base_cli.command_filters, command_filters) self.assertIs(base_cli.command_protocol, command_protocol) self.assertIs(base_cli.typer, typer) + self.assertIs(base_cli.json_contracts, json_contracts) self.assertTrue(issubclass(base_cli.ConfigurationError, ValueError)) def test_module_all_surfaces_are_explicit(self) -> None: @@ -127,6 +140,21 @@ def test_module_all_surfaces_are_explicit(self) -> None: set(typer.__all__), {"TyperAdapter", "attach_typer", "get_typer_command"}, ) + self.assertEqual( + set(json_contracts.__all__), + { + "JSON_CONTRACT_VERSION", + "JSON_ERROR_SCHEMA", + "JSON_LOG_SCHEMA", + "JSON_OUTPUT_SCHEMA", + "JsonLogFormatter", + "MAX_JSON_LOG_MESSAGE_LENGTH", + "error_envelope", + "success_envelope", + "dumps_envelope", + "redact_json_value", + }, + ) def test_entry_points_have_docstrings(self) -> None: self.assertTrue(base_cli.App.__doc__)