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.