From fafed7b842dd94dacd62c7679c02261298c614cc Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 12 Jun 2026 20:27:50 +0000 Subject: [PATCH] Add root -v/--verbose flag for stderr diagnostics The CLI had no way to see what it was doing on the wire: library loggers were actively silenced so stderr stayed clean next to normalized errors, and diagnosing an auth or connectivity problem meant reading code. A new root flag closes that gap (counted, gh/speechmatics style): - `-v` surfaces request-level logs (httpx and friends at INFO) - `-vv` adds wire-level detail (websockets frames, httpcore events at DEBUG) aai_cli/debuglog.py installs one stderr handler with a redacting formatter; config.resolve_api_key and AppState.resolve_session register the API key and session JWT at their resolution choke points so verbose output can never print them in clear (websockets logs the raw Authorization header at DEBUG during the handshake). The realtime silencers (aai_cli.ws, streaming/diagnostics) stand down while verbose mode is active, and the root callback logs the resolved environment. https://claude.ai/code/session_01Q6KZYc7FPWhyJkbQLUtq36 --- .importlinter | 2 + AGENTS.md | 1 + aai_cli/config.py | 13 ++++ aai_cli/context.py | 5 +- aai_cli/debuglog.py | 70 +++++++++++++++++ aai_cli/main.py | 17 +++- aai_cli/skills/aai-cli/SKILL.md | 7 +- aai_cli/streaming/diagnostics.py | 7 +- aai_cli/ws.py | 6 ++ pyproject.toml | 2 + tests/test_debuglog.py | 116 ++++++++++++++++++++++++++++ tests/test_streaming_diagnostics.py | 10 +++ tests/test_ws.py | 18 +++++ 13 files changed, 270 insertions(+), 4 deletions(-) create mode 100644 aai_cli/debuglog.py create mode 100644 tests/test_debuglog.py diff --git a/.importlinter b/.importlinter index a25a96b7..d5a80c7c 100644 --- a/.importlinter +++ b/.importlinter @@ -16,6 +16,7 @@ source_modules = aai_cli.config aai_cli.config_builder aai_cli.context + aai_cli.debuglog aai_cli.environments aai_cli.errors aai_cli.eval_data @@ -78,6 +79,7 @@ source_modules = aai_cli.client aai_cli.config aai_cli.config_builder + aai_cli.debuglog aai_cli.environments aai_cli.errors aai_cli.eval_data diff --git a/AGENTS.md b/AGENTS.md index 812f327a..67a520a0 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -173,6 +173,7 @@ Each file in `aai_cli/commands/` is a Typer sub-app (`transcribe`, `stream`, `ag - **`environments.py`** — a frozen `Environment` (api_base, streaming_host, llm_gateway_base, ams_base, stytch_*). `DEFAULT_ENV` is **`production`**; use `--sandbox` (or `--env sandbox000` / `AAI_ENV`) to target the sandbox. The active environment is a process-global set once at startup; precedence: `--env` → `AAI_ENV` → profile's stored env → default. A credential is only valid against the environment that minted it. - **`client.py`** — thin wrappers over the `assemblyai` SDK (`transcribe`, `list_transcripts`, `stream_audio`, etc.). It normalizes SDK exceptions: auth failures become a single clean `auth_failure()` `CLIError`; everything else becomes `APIError`. New SDK calls should follow this try/except shape. - **`errors.py`** — the `CLIError` hierarchy (each with `error_type` + `exit_code`). `output.py` emits errors to **stderr**; stdout stays clean for pipelines. `--json` switches to machine-readable output; it is never auto-enabled — `output.resolve_json()` deliberately keeps human text the default even when piped or agent-run. +- **`debuglog.py`** — the root `-v/--verbose` flag (count: `-v` request-level at INFO, `-vv` wire-level at DEBUG). The CLI normally configures no logging, and the realtime paths *silence* library loggers (`ws.py`, `streaming/diagnostics.py`); verbose mode installs one redacting stderr handler and those silencers stand down. Secrets are registered at their resolution choke points (`config.resolve_api_key`, `AppState.resolve_session`) and masked in every rendered record — websockets logs the raw Authorization header at DEBUG, so masking lives in the formatter, not at call sites. Stdlib-only on purpose: `config` (a Rich-free layer) imports it. ### Feature subsystems diff --git a/aai_cli/config.py b/aai_cli/config.py index 15e1848f..889bdcbc 100644 --- a/aai_cli/config.py +++ b/aai_cli/config.py @@ -14,6 +14,7 @@ import tomli_w from pydantic import BaseModel, ConfigDict, Field, ValidationError +from aai_cli import debuglog from aai_cli.errors import CLIError, NotAuthenticated KEYRING_SERVICE = "assemblyai-cli" @@ -408,6 +409,18 @@ def set_update_cache(*, last_check: float, latest_version: str | None) -> None: def resolve_api_key(*, profile: str | None = None, api_key_flag: str | None = None) -> str: + """The API key for SDK/gateway calls: --api-key flag > ASSEMBLYAI_API_KEY > keyring. + + Every resolved key is registered with the verbose-log redactor + (``debuglog.register_secret``) at this single choke point, so ``-v``/``-vv`` + diagnostics can never print it in clear no matter which library logs it. + """ + key = _resolve_api_key(profile=profile, api_key_flag=api_key_flag) + debuglog.register_secret(key) + return key + + +def _resolve_api_key(*, profile: str | None, api_key_flag: str | None) -> str: # Values are stripped at every tier: a whitespace-only key (e.g. a botched # `export ASSEMBLYAI_API_KEY=' '`) must read as "no key" (the clean exit-4 # not-signed-in path), not get sent as an illegal HTTP header byte string. diff --git a/aai_cli/context.py b/aai_cli/context.py index 578278d2..c2a3952b 100644 --- a/aai_cli/context.py +++ b/aai_cli/context.py @@ -9,7 +9,7 @@ import keyring.errors import typer -from aai_cli import config, environments, output, telemetry, update_check +from aai_cli import config, debuglog, environments, output, telemetry, update_check from aai_cli.environments import Environment from aai_cli.errors import APIError, CLIError, NotAuthenticated @@ -72,6 +72,9 @@ def resolve_session(self) -> tuple[int, str]: "can't access account commands." ), ) + # Registered like the API key in config.resolve_api_key: -v/-vv diagnostics + # must never print the session JWT in clear. + debuglog.register_secret(session["jwt"]) return account_id, session["jwt"] def env_override_warning(self) -> str | None: diff --git a/aai_cli/debuglog.py b/aai_cli/debuglog.py new file mode 100644 index 00000000..bc25535e --- /dev/null +++ b/aai_cli/debuglog.py @@ -0,0 +1,70 @@ +"""Opt-in diagnostic logging behind the root ``-v/--verbose`` flag. + +The CLI normally configures no logging at all, and the realtime paths actively +*silence* library loggers so stderr stays clean next to the CLI's normalized +errors (``aai_cli.ws``, ``aai_cli.streaming.diagnostics``). Verbose mode is the +inverse switch: ``enable`` installs one stderr handler so library logs become +visible — ``-v`` surfaces request-level lines (httpx and friends at INFO), +``-vv`` wire-level detail (websockets frames, httpcore events at DEBUG) — and +the silencers stand down while it is ``active``. + +Secrets never print in clear: ``register_secret`` records sensitive values as +they are resolved (API key, session JWT) and the handler's formatter masks them +in every rendered record. Masking must live in the formatter, not at call +sites, because the leak comes from *library* logs — websockets logs the raw +Authorization header at DEBUG during the handshake. + +Stdlib-only on purpose: ``config`` (a Rich-free library layer) registers +secrets here, so this module must not pull in Rich via ``output``/``theme``. +""" + +from __future__ import annotations + +import logging +import sys + +_MASK = "[redacted]" + +_verbosity = 0 +_secrets: set[str] = set() + + +class _RedactingFormatter(logging.Formatter): + """Formats records normally, then masks every registered secret.""" + + def format(self, record: logging.LogRecord) -> str: + text = super().format(record) + for secret in _secrets: + text = text.replace(secret, _MASK) + return text + + +def register_secret(value: str | None) -> None: + """Record a sensitive value so verbose output masks it. Empty values are + ignored (replacing "" would shred every record).""" + if value: + _secrets.add(value) + + +def active() -> bool: + """Whether verbose logging is on — the realtime silencers stand down then.""" + return _verbosity > 0 + + +def enable(verbosity: int) -> None: + """Install the stderr diagnostics handler: ``-v`` (1) at INFO, ``-vv``+ at DEBUG. + + Zero is the everyday no-op — no handler, the CLI stays log-silent. The + handler goes on the root logger so third-party loggers (httpx, websockets, + the assemblyai SDK) are covered without naming each one; stderr keeps the + errors-to-stderr / data-to-stdout split intact for pipelines. + """ + global _verbosity + if verbosity <= 0: + return + _verbosity = verbosity + handler = logging.StreamHandler(sys.stderr) + handler.setFormatter(_RedactingFormatter("[%(name)s] %(message)s")) + root = logging.getLogger() + root.addHandler(handler) + root.setLevel(logging.INFO if verbosity == 1 else logging.DEBUG) diff --git a/aai_cli/main.py b/aai_cli/main.py index 179a86ca..2b287831 100644 --- a/aai_cli/main.py +++ b/aai_cli/main.py @@ -1,5 +1,6 @@ from __future__ import annotations +import logging import sys from types import ModuleType from typing import TYPE_CHECKING @@ -19,7 +20,7 @@ # context type, not the upstream click.Context. Imported for typing only. from typer._click.core import Context as ClickContext -from aai_cli import __version__, argscan, environments, help_panels, output, stdio, theme +from aai_cli import __version__, argscan, debuglog, environments, help_panels, output, stdio, theme from aai_cli.commands import ( account, agent, @@ -286,6 +287,8 @@ def _profile_has_key(state: AppState) -> bool: # honor the request. _RAW_ARGS_META_KEY = "aai_raw_args" +_LOG = logging.getLogger("aai_cli") + def _sandbox_conflict_warning(sandbox: bool, env: str | None) -> str | None: """A warning when ``--sandbox`` and a contradictory ``--env`` are both passed. @@ -341,6 +344,13 @@ def main( quiet: bool = typer.Option( False, "--quiet", "-q", help="Suppress non-essential messages (warnings, hints)." ), + verbose: int = typer.Option( + 0, + "--verbose", + "-v", + count=True, + help="Log diagnostics to stderr (-v: requests, -vv: wire-level detail).", + ), # Underscore name: the eager callback does the work, so the parameter is intentionally # unused in the body (avoids ARG001 without a `del`). _version: bool = typer.Option( @@ -358,6 +368,9 @@ def main( # The command's own --json flag isn't parsed yet, so sniff the pending command line: # a root-callback failure (e.g. bad --env) still emits the JSON error shape when the # invocation opted into JSON, and renders human text on stderr otherwise. + # Enabled before anything else runs so even environment/profile resolution + # failures can be diagnosed with -v. + debuglog.enable(verbose) raw_args: list[str] = ctx.meta.get(_RAW_ARGS_META_KEY, []) json_mode = output.resolve_json(explicit=argscan.requests_json(raw_args)) conflict_warning = _sandbox_conflict_warning(sandbox, env) @@ -370,6 +383,8 @@ def main( except CLIError as err: output.emit_error(err, json_mode=json_mode) raise typer.Exit(code=err.exit_code) from None + active_env = environments.active() + _LOG.debug("environment: %s (%s)", active_env.name, active_env.api_base) for warning in (conflict_warning, state.env_override_warning()): if warning and not quiet: # Surfaced in JSON mode too (as {"warning": …}), so a `--json` pipeline gets diff --git a/aai_cli/skills/aai-cli/SKILL.md b/aai_cli/skills/aai-cli/SKILL.md index f3f93cd9..ec0f8570 100644 --- a/aai_cli/skills/aai-cli/SKILL.md +++ b/aai_cli/skills/aai-cli/SKILL.md @@ -33,9 +33,14 @@ suddenly returns auth errors, check you are on the same `--env` you logged in under. **Profiles.** `--profile ` selects a named credential set. Global flags -(`--profile`, `--env`, `--sandbox`) go *before* the subcommand: +(`--profile`, `--env`, `--sandbox`, `-v/--verbose`) go *before* the subcommand: `assembly --sandbox transcribe call.mp3`. +**Diagnostics.** `assembly -v ` logs request-level diagnostics to +stderr (HTTP requests and statuses); `-vv` adds wire-level detail (WebSocket +frames, connection events). Secrets (API key, session JWT) are redacted from +that output. Use this to debug auth/connectivity instead of guessing. + ## Output contract (read this before parsing output) - **Data goes to stdout; errors and progress go to stderr.** Piping stdout is diff --git a/aai_cli/streaming/diagnostics.py b/aai_cli/streaming/diagnostics.py index aeed2541..3d68a988 100644 --- a/aai_cli/streaming/diagnostics.py +++ b/aai_cli/streaming/diagnostics.py @@ -12,6 +12,7 @@ import logging from collections.abc import Callable +from aai_cli import debuglog from aai_cli import ws as wsutil from aai_cli.errors import APIError, CLIError, NotAuthenticated @@ -30,9 +31,13 @@ def silence_streaming_logging() -> None: """Silence the library loggers that would dirty stderr during a realtime run. Extends the shared websockets silencing (``aai_cli.ws``) with the assemblyai - SDK's streaming logger, which only the `stream` path uses. Idempotent. + SDK's streaming logger, which only the `stream` path uses. Idempotent. Stands + down (like ``aai_cli.ws``) under the root ``-v/--verbose`` flag, where library + logs are the requested output. """ wsutil.silence_websockets_logging() + if debuglog.active(): + return logging.getLogger(SDK_STREAMING_LOGGER).setLevel(logging.CRITICAL) diff --git a/aai_cli/ws.py b/aai_cli/ws.py index 65dff4ba..17622cb6 100644 --- a/aai_cli/ws.py +++ b/aai_cli/ws.py @@ -9,6 +9,7 @@ import logging +from aai_cli import debuglog from aai_cli.errors import APIError, CLIError, auth_failure, is_auth_failure # A pre-upgrade HTTP 403 on the WebSocket handshake is NOT a rejected key (it also @@ -31,7 +32,12 @@ def silence_websockets_logging() -> None: ``websockets.client`` logger, which would land on stderr right next to our clean CLIError. Those internals are never user-actionable from the CLI, so raise the loggers above every level they emit at. Idempotent: re-setting the level is a no-op. + + Stands down under the root ``-v/--verbose`` flag: wire-level frames are exactly + what ``-vv`` exists to show, so verbose mode leaves the loggers untouched. """ + if debuglog.active(): + return for name in WEBSOCKETS_LOGGERS: logging.getLogger(name).setLevel(logging.CRITICAL) diff --git a/pyproject.toml b/pyproject.toml index 11ae0f5c..1a644852 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -256,6 +256,8 @@ max-statements = 40 "aai_cli/output.py" = ["T201"] # The active environment is process-global startup state by design. "aai_cli/environments.py" = ["PLW0603"] +# Verbosity is process-global startup state by design (mirrors environments.py). +"aai_cli/debuglog.py" = ["PLW0603"] # BaseHTTPRequestHandler.log_message requires a parameter named `format`. "aai_cli/auth/loopback.py" = ["A002"] # Template constants include URL path names such as TOKEN_PATH, not credentials. diff --git a/tests/test_debuglog.py b/tests/test_debuglog.py new file mode 100644 index 00000000..07f29e44 --- /dev/null +++ b/tests/test_debuglog.py @@ -0,0 +1,116 @@ +"""Tests for the opt-in diagnostic logging behind the root -v/--verbose flag +(aai_cli/debuglog.py): the stderr handler, secret redaction, and the places +that register secrets (config.resolve_api_key, AppState.resolve_session). +""" + +from __future__ import annotations + +import logging + +import pytest +from typer.testing import CliRunner + +from aai_cli import config, debuglog +from aai_cli import ws as wsutil +from aai_cli.context import AppState +from aai_cli.main import app + +runner = CliRunner() + + +@pytest.fixture(autouse=True) +def reset_debuglog(monkeypatch): + # enable() mutates process-global state (the root logger and the module's + # verbosity/secret registries); snapshot and restore so pytest-randomly + # ordering can't leak a verbose run into unrelated tests. + root = logging.getLogger() + previous_handlers = list(root.handlers) + previous_level = root.level + # Logger levels are process-global too: any earlier test that exercised the + # realtime silencers left the websockets loggers clamped at CRITICAL, which + # would swallow the wire-level records asserted here. Reset them so these + # tests are order-independent under pytest-randomly, then restore. + wire_loggers = [logging.getLogger(name) for name in wsutil.WEBSOCKETS_LOGGERS] + previous_wire_levels = [logger.level for logger in wire_loggers] + for logger in wire_loggers: + logger.setLevel(logging.NOTSET) + monkeypatch.setattr(debuglog, "_verbosity", 0) + monkeypatch.setattr(debuglog, "_secrets", set()) + yield + root.handlers[:] = previous_handlers + root.setLevel(previous_level) + for logger, level in zip(wire_loggers, previous_wire_levels, strict=True): + logger.setLevel(level) + + +def test_enable_zero_is_the_everyday_no_op(): + root = logging.getLogger() + handlers_before = list(root.handlers) + level_before = root.level + debuglog.enable(0) + assert not debuglog.active() + assert root.handlers == handlers_before + assert root.level == level_before + + +def test_enable_one_logs_info_but_not_debug_to_stderr(capsys): + debuglog.enable(1) + assert debuglog.active() + assert logging.getLogger().level == logging.INFO + probe = logging.getLogger("aai_cli.test_probe") + probe.info("hello request log") + probe.debug("wire frame detail") + err = capsys.readouterr().err + assert "[aai_cli.test_probe] hello request log" in err + assert "wire frame detail" not in err + + +def test_enable_two_logs_wire_level_debug(capsys): + debuglog.enable(2) + assert logging.getLogger().level == logging.DEBUG + logging.getLogger("websockets.client").debug("> TEXT frame") + assert "[websockets.client] > TEXT frame" in capsys.readouterr().err + + +def test_registered_secrets_are_masked_in_every_record(capsys): + debuglog.enable(2) + debuglog.register_secret("sk_super_secret_value") + logging.getLogger("websockets.client").debug("authorization: sk_super_secret_value") + err = capsys.readouterr().err + assert "sk_super_secret_value" not in err + assert "authorization: [redacted]" in err + + +def test_register_secret_ignores_empty_values(): + debuglog.register_secret(None) + debuglog.register_secret("") + assert debuglog._secrets == set() + + +def test_resolve_api_key_registers_the_key_for_redaction(monkeypatch): + monkeypatch.setenv("ASSEMBLYAI_API_KEY", "sk_env_key_for_redaction") + assert config.resolve_api_key() == "sk_env_key_for_redaction" + assert "sk_env_key_for_redaction" in debuglog._secrets + + +def test_resolve_session_registers_the_jwt_for_redaction(monkeypatch): + monkeypatch.setattr(config, "get_session", lambda profile: {"jwt": "jwt_secret", "token": "t"}) + monkeypatch.setattr(config, "get_account_id", lambda profile: 42) + assert AppState().resolve_session() == (42, "jwt_secret") + assert "jwt_secret" in debuglog._secrets + + +def test_root_vv_flag_enables_wire_level_diagnostics(): + result = runner.invoke(app, ["-vv"]) # bare invocation: prints help and exits 0 + assert result.exit_code == 0 + assert debuglog.active() + assert logging.getLogger().level == logging.DEBUG + + +def test_root_v_flag_sets_info_and_logs_the_environment(caplog): + caplog.set_level(logging.DEBUG, logger="aai_cli") + result = runner.invoke(app, ["-v"]) + assert result.exit_code == 0 + assert logging.getLogger().level == logging.INFO + assert "environment" in caplog.text + assert "production" in caplog.text diff --git a/tests/test_streaming_diagnostics.py b/tests/test_streaming_diagnostics.py index f597c70a..5eeb2578 100644 --- a/tests/test_streaming_diagnostics.py +++ b/tests/test_streaming_diagnostics.py @@ -9,6 +9,7 @@ import pytest +from aai_cli import debuglog from aai_cli.errors import APIError, NotAuthenticated from aai_cli.streaming.diagnostics import ( SDK_STREAMING_LOGGER, @@ -67,6 +68,15 @@ def test_silence_streaming_logging_suppresses_the_sdk_client_logger(): root.removeHandler(spy) +@pytest.mark.usefixtures("reset_levels") +def test_silence_streaming_logging_stands_down_in_verbose_mode(monkeypatch): + # Library logs are the requested output under -v/-vv; nothing gets clamped. + monkeypatch.setattr(debuglog, "_verbosity", 1) + silence_streaming_logging() + for name in (SDK_STREAMING_LOGGER, *WEBSOCKETS_LOGGERS): + assert logging.getLogger(name).level == logging.NOTSET + + def test_sdk_streaming_logger_is_the_assemblyai_parent(): assert SDK_STREAMING_LOGGER == "assemblyai.streaming" diff --git a/tests/test_ws.py b/tests/test_ws.py index 223bc273..11895c73 100644 --- a/tests/test_ws.py +++ b/tests/test_ws.py @@ -9,6 +9,7 @@ import logging import types +from aai_cli import debuglog from aai_cli.errors import APIError, NotAuthenticated from aai_cli.ws import ( WEBSOCKETS_LOGGERS, @@ -98,6 +99,23 @@ def test_silence_websockets_logging_raises_both_loggers_to_critical(): lg.setLevel(level) +def test_silence_websockets_logging_stands_down_in_verbose_mode(monkeypatch): + # -vv exists to show wire-level frames, so the silencer must leave the + # websockets loggers untouched while verbose mode is active. + monkeypatch.setattr(debuglog, "_verbosity", 2) + loggers = [logging.getLogger(name) for name in WEBSOCKETS_LOGGERS] + previous = [lg.level for lg in loggers] + try: + for lg in loggers: + lg.setLevel(logging.NOTSET) + silence_websockets_logging() + for lg in loggers: + assert lg.level == logging.NOTSET + finally: + for lg, level in zip(loggers, previous, strict=True): + lg.setLevel(level) + + def test_websockets_logger_names_cover_the_sync_client(): # The sync client logs through "websockets.client"; the parent covers any # future child loggers.