diff --git a/.ai/task-manager/archive/18--http-debug-logging/plan-18--http-debug-logging.md b/.ai/task-manager/archive/18--http-debug-logging/plan-18--http-debug-logging.md new file mode 100644 index 0000000..8ace91b --- /dev/null +++ b/.ai/task-manager/archive/18--http-debug-logging/plan-18--http-debug-logging.md @@ -0,0 +1,206 @@ +--- +id: 18 +summary: "Add --debug flag for HTTP request/response logging with credential redaction, restructure log levels across CLI and TUI" +created: 2026-03-11 +--- + +# Plan: HTTP Debug Logging with Credential Redaction + +## Original Work Order +> Extend debug logging to show HTTP requests and responses, redacting keys, tokens, and credentials. The CLI / TUI tools should have `--verbose`, which is the existing behaviour (rename the help text to `Enable verbose logging`). Then, we should have a `--debug` parameter which is "Enable verbose logging including HTTP requests and responses". Internally, --verbose should map to an info log level, and --debug should map to a debug log level. With nothing specified, our log level should default to warn. + +## Plan Clarifications + +| Question | Answer | +|---|---| +| There are currently zero `_LOGGER.info()` calls in the codebase. `--verbose` (INFO) would produce no additional output vs default (WARNING). Should some existing DEBUG messages be promoted to INFO? | Yes. Promote `client.py`'s request summary line (`"GET /url -> 200"`) and key `auth.py` lifecycle messages (silent token acquisition, auth success) to INFO. Keep `protocol.py` decode/encode detail and full HTTP request/response traces at DEBUG. | + +## Executive Summary + +The library already has partial HTTP debug logging in `b2c_login.py` (via `_log_request`/`_log_response` helpers) but the main API client in `client.py` only logs a one-line summary at DEBUG level. Meanwhile, the `--verbose` flag currently maps directly to DEBUG, providing no intermediate INFO level. Additionally, there are zero INFO-level log calls in the entire codebase, so the intermediate tier would be invisible without re-leveling some messages. + +This plan restructures the logging tiers so `--verbose` gives INFO-level insight (request summaries, auth lifecycle) while `--debug` unlocks full HTTP request/response tracing. The HTTP tracing in `client.py._request` will follow the same pattern already established in `b2c_login.py`, with a shared redaction utility to mask Bearer tokens, passwords, CSRF tokens, and other credentials before they reach the log output. Select existing DEBUG messages in `client.py` and `auth.py` will be promoted to INFO to populate the verbose tier. + +## Context + +### Current State vs Target State + +| Current State | Target State | Why? | +|---|---|---| +| `--verbose` maps to DEBUG | `--verbose` maps to INFO | Provides a useful middle ground without overwhelming HTTP detail | +| No `--debug` flag exists | `--debug` maps to DEBUG | Unlocks full HTTP request/response tracing for troubleshooting | +| Default log level is WARNING | Default log level remains WARNING | No change needed | +| Help text says "Enable debug logging" | Help text says "Enable verbose logging" / "Enable verbose logging including HTTP requests and responses" | Accurate description of each flag's purpose | +| Zero `_LOGGER.info()` calls exist | Key messages in `client.py` and `auth.py` promoted to INFO | Makes `--verbose` produce useful output | +| `client.py._request` logs only `"GET /url -> 200"` at DEBUG | Summary line promoted to INFO; full headers/body logged at DEBUG | INFO gives request-level trace; DEBUG gives full HTTP detail | +| `b2c_login.py` has its own `_log_request`/`_log_response` | Shared helpers in `_http_logging.py` used by both modules | Consistent redaction of sensitive values | +| `b2c_login._log_request` redacts only `password` key in form data | Redaction covers Authorization headers, passwords, CSRF tokens, and cookie values | Prevents accidental credential leakage in logs | +| TUI `run_tui(verbose=bool)` sets DEBUG on verbose | TUI accepts a `log_level: int` and applies it directly | Supports both verbose and debug modes | + +### Background + +The `b2c_login.py` module already contains a well-structured pattern for HTTP debug logging (`_log_request` at line 117, `_log_response` at line 136). These use `>>>` and `<<<` prefixes and truncate response bodies to 2000 characters. The `client.py._request` method (line 135) is the single point through which all API calls flow, making it the ideal place to add equivalent tracing. The `b2c_login.py` redaction currently only masks the `password` form field; Bearer tokens in Authorization headers and CSRF tokens are logged in plain text. + +The existing DEBUG messages across the codebase fall into three categories: +- **Auth lifecycle** (`auth.py`): "Attempting silent token acquisition", "Token acquired silently", "Authentication successful" — useful operational context, appropriate for INFO. +- **Request summary** (`client.py`): `"GET /url -> 200"` — useful at INFO to see API traffic without full payloads. +- **Protocol decode/encode** (`protocol.py`): Byte-level parameter decoding — noisy, should remain at DEBUG. + +## Architectural Approach + +```mermaid +flowchart TD + CLI["CLI / TUI entry point"] + CLI -->|"--debug"| DEBUG["logging.DEBUG"] + CLI -->|"--verbose"| INFO["logging.INFO"] + CLI -->|"(default)"| WARN["logging.WARNING"] + + INFO --> SUMMARY["client.py: request summary line\nauth.py: lifecycle messages"] + DEBUG --> FULL["Full HTTP headers + body\nprotocol decode/encode detail"] + DEBUG --> B2C["b2c_login.py HTTP traces"] + + FULL -->|"redacted via"| REDACT["_http_logging.redact_headers()"] + B2C -->|"redacted via"| REDACT + + REDACT --> OUTPUT["Sanitized log output"] +``` + +### Shared HTTP Logging Module + +**Objective**: Centralise HTTP debug logging and credential redaction into a single module shared by `client.py` and `b2c_login.py`. + +A new private module `src/flameconnect/_http_logging.py` will contain: + +- **`redact_headers(headers: Mapping[str, str]) -> dict[str, str]`** — Returns a copy with sensitive values replaced by `"***"`. Keys matched case-insensitively: `Authorization`, `Cookie`, `Set-Cookie`, `X-CSRF-TOKEN`. For `Authorization`, the scheme prefix is preserved (e.g. `"Bearer ***"`). +- **`redact_body(data: dict[str, str]) -> dict[str, str]`** — Returns a copy with the `password` key redacted. This is the form-data redaction already in `b2c_login.py`. +- **`log_request(logger, method, url, *, headers=None, data=None, params=None)`** — Logs at DEBUG using `>>>` prefix. Applies `redact_headers` to headers and `redact_body` to data before logging. +- **`log_response(logger, response, body=None)`** — Logs at DEBUG using `<<<` prefix. Applies `redact_headers` to response headers. Truncates body to 2000 characters. + +The module name `_http_logging` (not `_logging`) avoids visual confusion with the stdlib `logging` module. All functions accept a `logger` parameter rather than using a module-level logger, so each caller's messages appear under their own logger name (e.g. `flameconnect.client`, `flameconnect.b2c_login`). + +### Log Level Promotion + +**Objective**: Populate the INFO tier so `--verbose` produces meaningful output. + +Specific changes to existing log calls: + +- **`client.py:174`**: `_LOGGER.debug("%s %s -> %s", method, url, response.status)` → `_LOGGER.info(...)`. This is the request summary visible with `--verbose`. +- **`auth.py:126`**: `"Attempting silent token acquisition"` → `_LOGGER.info(...)` +- **`auth.py:134`**: `"Token acquired silently (refreshed from cache)"` → `_LOGGER.info(...)` +- **`auth.py:138`**: `"No cached token, initiating interactive auth code flow"` → `_LOGGER.info(...)` +- **`auth.py:189`**: `"Authentication successful, token acquired"` → `_LOGGER.info(...)` + +All other DEBUG messages (protocol decode/encode, auth internals like "Exchanging authorization code", `b2c_login.py` HTTP traces) remain at DEBUG. + +### Client HTTP Debug Logging + +**Objective**: Add full HTTP request/response debug logging to `FlameConnectClient._request`, matching the pattern already used in `b2c_login.py`. + +The `_request` method in `client.py` will call the shared `log_request` before the HTTP call and `log_response` after, both at DEBUG level. The existing summary line stays but is promoted to INFO (see above), so `--verbose` users see `"GET /url -> 200"` while `--debug` users additionally see headers, body, and response detail. Response bodies will be truncated to 2000 characters, consistent with the existing `b2c_login.py` behaviour. + +### CLI Flag Restructuring + +**Objective**: Add `--debug` flag and adjust `--verbose` semantics across CLI and TUI entry points. + +In `build_parser()`: rename `--verbose` help text to `"Enable verbose logging"` and add `--debug` with help text `"Enable verbose logging including HTTP requests and responses"`. The flags should be mutually exclusive (using `argparse.add_mutually_exclusive_group`). In `main()`, the log level selection becomes: `--debug` -> `DEBUG`, `--verbose` -> `INFO`, default -> `WARNING`. + +The `run_tui` function signature changes from `verbose: bool` to accept a `log_level: int` parameter (defaulting to `logging.WARNING`), and applies that level to the `flameconnect` logger. The `cmd_tui` and `async_main` callers will compute the appropriate level and pass it through. In the TUI's `DashboardScreen`, the log handler currently attaches to the `flameconnect` logger at whatever level is set — this behaviour continues unchanged, meaning DEBUG messages (including HTTP traces) will appear in the TUI messages panel when `--debug` is used. + +### b2c_login.py Migration + +**Objective**: Remove duplicated logging helpers from `b2c_login.py` and use the shared module. + +The `_log_request` and `_log_response` functions will be removed from `b2c_login.py` and replaced with imports from `flameconnect._http_logging`. All existing call sites will be updated to pass `_LOGGER` as the first argument. The password redaction in form data is handled by the shared `redact_body` function. + +## Risk Considerations and Mitigation Strategies + +
+Technical Risks + +- **Credential leakage in logs**: Sensitive tokens or passwords could appear in log output if redaction misses a field. + - **Mitigation**: Case-insensitive header matching against a known set of sensitive keys. Test coverage will verify redaction of Authorization, Cookie, password, and CSRF token values. +- **JSON response bodies containing tokens**: B2C token exchange responses may contain `access_token` fields in JSON bodies. + - **Mitigation**: Response body logging is only active at DEBUG level, which is opt-in for troubleshooting. The truncation to 2000 characters limits exposure. Full JSON body redaction is out of scope for this plan — users opting into `--debug` accept seeing raw (truncated) response content. +
+ +
+Implementation Risks + +- **Breaking existing test assertions**: Tests that assert on `--verbose` behaviour or mock logging calls will need updating. There are ~20 test references to `verbose` in `test_cli_commands.py`. + - **Mitigation**: Update tests alongside the implementation. Tests for `build_parser` will cover both `--verbose` and `--debug`. Tests for `async_main`/`cmd_tui` will pass `log_level` instead of `verbose`. +
+ +## Success Criteria + +### Primary Success Criteria +1. `flameconnect --debug list` logs full HTTP request headers (with Bearer token redacted), request body, response status, response headers, and truncated response body +2. `flameconnect --verbose list` shows INFO-level messages (request summaries, auth lifecycle) but no HTTP request/response detail +3. `flameconnect list` (no flag) shows only WARNING and above +4. All sensitive values (Authorization tokens, passwords, cookies, CSRF tokens) are redacted in debug output +5. `mypy` strict checking passes, `ruff` passes, test coverage remains at or above 95% + +## Resource Requirements + +### Development Skills +- Python async programming, `logging` module, `aiohttp` +- `argparse` mutually exclusive groups + +### Technical Infrastructure +- Existing dev toolchain: `uv`, `ruff`, `mypy`, `pytest` + +## Task Dependencies + +```mermaid +graph TD + 01[Task 01: Shared HTTP logging module] --> 03[Task 03: Integrate HTTP logging] + 02[Task 02: CLI flags & log level promotion] --> 03 +``` + +## Execution Blueprint + +**Validation Gates:** +- Reference: `/config/hooks/POST_PHASE.md` + +### ✅ Phase 1: Foundation +**Parallel Tasks:** +- ✔️ Task 01: Create shared HTTP logging module (`_http_logging.py`) +- ✔️ Task 02: CLI flag restructuring and log level promotion + +### ✅ Phase 2: Integration +**Parallel Tasks:** +- ✔️ Task 03: Integrate shared HTTP logging into client and b2c_login (depends on: 01, 02) + +### Execution Summary +- Total Phases: 2 +- Total Tasks: 3 +- Maximum Parallelism: 2 tasks (in Phase 1) +- Critical Path Length: 2 phases + +## Execution Summary + +**Status**: Completed Successfully +**Completed Date**: 2026-03-11 + +### Results +All three tasks completed across two phases. The implementation delivers: +- `src/flameconnect/_http_logging.py` — shared module with `redact_headers`, `redact_body`, `log_request`, `log_response` +- `--verbose` (INFO) and `--debug` (DEBUG) mutually exclusive CLI flags with correct log level mapping +- Full HTTP request/response tracing in `client.py._request` at DEBUG level with credential redaction +- `b2c_login.py` migrated to shared helpers (local copies removed) +- 5 auth/client messages promoted from DEBUG to INFO for `--verbose` visibility +- `run_tui()` signature updated from `verbose: bool` to `log_level: int` +- 23 new tests in `test_http_logging.py`; all 1230 tests pass + +### Noteworthy Events +- One pre-existing test (`TestRequestDebugLog.test_request_debug_log_format` in `test_client.py`) failed after promoting the request summary to INFO — updated to check INFO level instead of DEBUG. +- `_http_logging.py` `data` parameter type was widened from `Mapping[str, str]` to `Mapping[str, Any]` to accept `client.py`'s JSON body payloads. +- `client.py._request` was refactored to read `response.text()` first and then `json.loads()` instead of `response.json()`, enabling the response body to be logged before parsing. + +### Recommendations +No follow-up actions required. + +## Notes + +### Change Log +- 2026-03-11: Initial plan created +- 2026-03-11: Refinement — added Log Level Promotion section to address zero INFO-level messages; renamed module from `_logging.py` to `_http_logging.py` to avoid stdlib shadowing; specified function signatures for shared module; added JSON body token risk; clarified that `log_request`/`log_response` accept a logger parameter for proper logger namespacing diff --git a/.ai/task-manager/archive/18--http-debug-logging/tasks/01--shared-http-logging-module.md b/.ai/task-manager/archive/18--http-debug-logging/tasks/01--shared-http-logging-module.md new file mode 100644 index 0000000..baa3f55 --- /dev/null +++ b/.ai/task-manager/archive/18--http-debug-logging/tasks/01--shared-http-logging-module.md @@ -0,0 +1,50 @@ +--- +id: 1 +group: "http-debug-logging" +dependencies: [] +status: "completed" +created: 2026-03-11 +skills: + - python + - logging +--- +# Create shared HTTP logging module + +## Objective +Create `src/flameconnect/_http_logging.py` with redaction utilities and HTTP logging helpers that will be shared by `client.py` and `b2c_login.py`. + +## Skills Required +- Python stdlib `logging` module +- Type annotations compatible with mypy strict mode + +## Acceptance Criteria +- [ ] `src/flameconnect/_http_logging.py` exists with all four functions +- [ ] `redact_headers` redacts Authorization (preserving scheme prefix), Cookie, Set-Cookie, X-CSRF-TOKEN (case-insensitive matching) +- [ ] `redact_body` redacts the `password` key in form data dicts +- [ ] `log_request` logs method, URL, redacted headers, redacted body, and params at DEBUG level using `>>>` prefix +- [ ] `log_response` logs status, URL, redacted headers, and truncated body (2000 chars) at DEBUG level using `<<<` prefix +- [ ] All functions accept a `logger` parameter (not a module-level logger) +- [ ] `log_response` accepts an `aiohttp.ClientResponse` for status/url/headers, and an optional `str` body +- [ ] mypy strict passes, ruff passes + +## Technical Requirements +- Function signatures as specified in the plan: + - `redact_headers(headers: Mapping[str, str]) -> dict[str, str]` + - `redact_body(data: Mapping[str, str]) -> dict[str, str]` + - `log_request(logger: logging.Logger, method: str, url: str, *, headers: Mapping[str, str] | None = None, data: Mapping[str, str] | None = None, params: Mapping[str, str] | None = None) -> None` + - `log_response(logger: logging.Logger, response: aiohttp.ClientResponse, body: str | None = None) -> None` +- Case-insensitive header key matching for redaction +- For `Authorization` header: preserve scheme prefix (e.g. `"Bearer ***"`) +- Body truncation to 2000 characters with `"... (N bytes total)"` suffix + +## Input Dependencies +None — this is a new module. + +## Output Artifacts +- `src/flameconnect/_http_logging.py` — shared module imported by tasks 02 and 03. + +## Implementation Notes +- Port the `>>>` / `<<<` logging pattern from `b2c_login.py` lines 117-151. +- The `_SENSITIVE_HEADERS` set should use lowercased keys for case-insensitive matching. +- Use `from __future__ import annotations` for forward references. +- Import `aiohttp` under `TYPE_CHECKING` to avoid a hard runtime dependency for the type signature. diff --git a/.ai/task-manager/archive/18--http-debug-logging/tasks/02--cli-flags-and-log-level-promotion.md b/.ai/task-manager/archive/18--http-debug-logging/tasks/02--cli-flags-and-log-level-promotion.md new file mode 100644 index 0000000..a249e37 --- /dev/null +++ b/.ai/task-manager/archive/18--http-debug-logging/tasks/02--cli-flags-and-log-level-promotion.md @@ -0,0 +1,54 @@ +--- +id: 2 +group: "http-debug-logging" +dependencies: [] +status: "completed" +created: 2026-03-11 +skills: + - python + - argparse +--- +# CLI flag restructuring and log level promotion + +## Objective +Add `--debug` flag, adjust `--verbose` semantics, promote key DEBUG messages to INFO, and update TUI `run_tui` signature. + +## Skills Required +- Python `argparse` (mutually exclusive groups) +- Python `logging` module + +## Acceptance Criteria +- [ ] `--verbose` and `--debug` are mutually exclusive flags in `build_parser()` +- [ ] `--verbose` help text is `"Enable verbose logging"` +- [ ] `--debug` help text is `"Enable verbose logging including HTTP requests and responses"` +- [ ] `main()` maps: `--debug` → `logging.DEBUG`, `--verbose` → `logging.INFO`, default → `logging.WARNING` +- [ ] `run_tui` signature changes from `verbose: bool` to `log_level: int` (default `logging.WARNING`) +- [ ] `cmd_tui` and `async_main` pass computed `log_level` to `run_tui` +- [ ] `client.py:174` request summary promoted from `_LOGGER.debug` to `_LOGGER.info` +- [ ] `auth.py` lines 126, 134, 138, 189 promoted from `_LOGGER.debug` to `_LOGGER.info` +- [ ] All existing tests updated to pass with new flag structure and `log_level` parameter +- [ ] mypy strict passes, ruff passes + +## Technical Requirements +- Use `parser.add_mutually_exclusive_group()` for `--verbose`/`--debug` +- In `main()`: `logging.basicConfig(level=logging.DEBUG if args.debug else logging.INFO if args.verbose else logging.WARNING)` +- In `run_tui`: replace `if verbose: fc_logger.setLevel(logging.DEBUG)` with `fc_logger.setLevel(log_level)` +- Update `cmd_tui` signature from `verbose: bool` to `log_level: int` +- In `async_main`: compute `log_level` from `args.verbose`/`args.debug` and pass to `run_tui`/`cmd_tui` +- Update all test assertions that reference `verbose=True/False` to use `log_level=...` + +## Input Dependencies +None — flag restructuring and log level changes are independent of the new `_http_logging` module. + +## Output Artifacts +- Modified `src/flameconnect/cli.py` — new flags, updated `main()`, `cmd_tui`, `async_main` +- Modified `src/flameconnect/tui/app.py` — updated `run_tui` signature +- Modified `src/flameconnect/client.py` — one line promoted to INFO +- Modified `src/flameconnect/auth.py` — four lines promoted to INFO +- Updated tests in `tests/test_cli_commands.py` + +## Implementation Notes +- The `-v` short flag should remain on `--verbose`. +- `--debug` does not need a short flag. +- When neither flag is given, `args.verbose` and `args.debug` are both `False`. +- The TUI's `DashboardScreen._log_handler` attaches at whatever level the logger is set to — no changes needed there. diff --git a/.ai/task-manager/archive/18--http-debug-logging/tasks/03--integrate-http-logging.md b/.ai/task-manager/archive/18--http-debug-logging/tasks/03--integrate-http-logging.md new file mode 100644 index 0000000..05b00f9 --- /dev/null +++ b/.ai/task-manager/archive/18--http-debug-logging/tasks/03--integrate-http-logging.md @@ -0,0 +1,51 @@ +--- +id: 3 +group: "http-debug-logging" +dependencies: [1, 2] +status: "completed" +created: 2026-03-11 +skills: + - python + - aiohttp +--- +# Integrate shared HTTP logging into client and b2c_login + +## Objective +Wire the shared `_http_logging` module into `client.py._request` and migrate `b2c_login.py` to use the shared helpers. Add tests for all new and migrated functionality. + +## Skills Required +- Python async programming with `aiohttp` +- Python `logging` module + +## Acceptance Criteria +- [ ] `client.py._request` calls `log_request` before the HTTP call and `log_response` after +- [ ] `b2c_login.py` no longer defines its own `_log_request` or `_log_response` functions +- [ ] `b2c_login.py` imports and uses `log_request`/`log_response` from `flameconnect._http_logging` +- [ ] All `b2c_login.py` call sites pass `_LOGGER` as the first argument +- [ ] `redact_headers` is tested: Authorization shows `"Bearer ***"`, Cookie/Set-Cookie/X-CSRF-TOKEN show `"***"`, non-sensitive headers pass through, case-insensitive matching works +- [ ] `redact_body` is tested: password key is redacted, other keys pass through +- [ ] `log_request` and `log_response` are tested: correct DEBUG-level calls, redaction applied, body truncation works +- [ ] `client.py._request` HTTP logging is tested: headers and body logged at DEBUG with redaction +- [ ] Existing `b2c_login` tests still pass (no behaviour change, just code moved) +- [ ] mypy strict passes, ruff passes, test coverage ≥ 95% + +## Technical Requirements +- In `client.py._request`, call `log_request` with the headers dict (including Authorization) and optional JSON body +- In `client.py._request`, after getting the response, read the body text for logging, then call `log_response` +- Note: `_request` currently calls `response.json()` — to log the body, capture `response.text()` first, then parse JSON from that text (or log after `json()` by serializing the result) +- In `b2c_login.py`, replace `from`-less `_log_request(...)` calls with `log_request(_LOGGER, ...)` and similarly for `_log_response` + +## Input Dependencies +- Task 01: `src/flameconnect/_http_logging.py` must exist +- Task 02: `client.py` request summary line must already be promoted to INFO (so DEBUG logging additions don't conflict) + +## Output Artifacts +- Modified `src/flameconnect/client.py` — HTTP debug logging added to `_request` +- Modified `src/flameconnect/b2c_login.py` — local helpers removed, shared helpers imported +- New test file `tests/test_http_logging.py` — tests for `_http_logging` module +- Updated `tests/test_b2c_login.py` — adjusted for shared helper imports if needed + +## Implementation Notes +- For `client.py._request`, consider reading `await response.text()` and then using `json.loads()` to parse it, rather than `response.json()`, so the raw body is available for logging. Alternatively, log `json.dumps(result)` after parsing. +- The `b2c_login.py` migration is a straightforward find-and-replace: `_log_request(` → `log_request(_LOGGER, ` and `_log_response(` → `log_response(_LOGGER, `. +- Ensure tests cover the edge case where `body` is `None` in `log_response`. diff --git a/README.md b/README.md index e8b6abf..a04a9de 100644 --- a/README.md +++ b/README.md @@ -111,7 +111,7 @@ async with FlameConnectClient(auth=auth, session=my_session) as client: ## CLI Usage The `flameconnect` command provides a straightforward interface for controlling your -fireplace from the terminal. Add `-v` to any command for debug logging. +fireplace from the terminal. Add `-v` to any command for verbose logging. All examples below use `flameconnect` directly, but you can substitute `uv tool run flameconnect` if you haven't installed the package (e.g. diff --git a/src/flameconnect/_http_logging.py b/src/flameconnect/_http_logging.py new file mode 100644 index 0000000..3aa9859 --- /dev/null +++ b/src/flameconnect/_http_logging.py @@ -0,0 +1,86 @@ +"""Shared HTTP logging helpers with credential redaction.""" + +from __future__ import annotations + +from typing import TYPE_CHECKING + +if TYPE_CHECKING: + import logging + from collections.abc import Mapping + from typing import Any + + import aiohttp + +_SENSITIVE_HEADERS: frozenset[str] = frozenset( + {"authorization", "cookie", "set-cookie", "x-csrf-token"} +) + + +def redact_headers(headers: Mapping[str, str]) -> dict[str, str]: + """Return a copy of *headers* with sensitive values replaced by ``"***"``. + + Keys are matched case-insensitively against :data:`_SENSITIVE_HEADERS`. + For the ``Authorization`` header the scheme prefix is preserved + (e.g. ``"Bearer ***"``). + """ + result: dict[str, str] = {} + for key, value in headers.items(): + if key.lower() in _SENSITIVE_HEADERS: + if key.lower() == "authorization": + parts = value.split(None, 1) + if len(parts) == 2: # noqa: PLR2004 + result[key] = f"{parts[0]} ***" + else: + result[key] = "***" + else: + result[key] = "***" + else: + result[key] = value + return result + + +_SENSITIVE_BODY_KEYS: frozenset[str] = frozenset({"password"}) + + +def redact_body(data: Mapping[str, Any]) -> dict[str, Any]: + """Return a copy of *data* with sensitive keys redacted to ``"***"``. + + Keys are matched case-insensitively against :data:`_SENSITIVE_BODY_KEYS`. + """ + return { + k: ("***" if k.lower() in _SENSITIVE_BODY_KEYS else v) for k, v in data.items() + } + + +def log_request( + logger: logging.Logger, + method: str, + url: str, + *, + headers: Mapping[str, str] | None = None, + data: Mapping[str, Any] | None = None, + params: Mapping[str, str] | None = None, +) -> None: + """Log an outgoing HTTP request at DEBUG level.""" + logger.debug(">>> %s %s", method, url) + if params: + logger.debug(">>> params: %s", dict(params)) + if headers: + logger.debug(">>> headers: %s", redact_headers(headers)) + if data: + logger.debug(">>> body: %s", redact_body(data)) + + +def log_response( + logger: logging.Logger, + response: aiohttp.ClientResponse, + body: str | None = None, +) -> None: + """Log an incoming HTTP response at DEBUG level.""" + logger.debug("<<< %s %s", response.status, response.url) + logger.debug("<<< headers: %s", redact_headers(response.headers)) + if body is not None: + preview = body[:2000] + if len(body) > 2000: # noqa: PLR2004 + preview += f"... ({len(body)} bytes total)" + logger.debug("<<< body: %s", preview) diff --git a/src/flameconnect/auth.py b/src/flameconnect/auth.py index ceff8b7..2edae05 100644 --- a/src/flameconnect/auth.py +++ b/src/flameconnect/auth.py @@ -123,7 +123,7 @@ async def get_token(self) -> str: app, cache = await asyncio.to_thread(self._build_app) # Try silent token acquisition from cache (uses refresh token) - _LOGGER.debug("Attempting silent token acquisition") + _LOGGER.info("Attempting silent token acquisition") accounts: list[Any] = app.get_accounts() if accounts: result: dict[str, Any] | None = await asyncio.to_thread( @@ -131,11 +131,11 @@ async def get_token(self) -> str: ) if result and "access_token" in result: await asyncio.to_thread(self._save_cache, cache) - _LOGGER.debug("Token acquired silently (refreshed from cache)") + _LOGGER.info("Token acquired silently (refreshed from cache)") return str(result["access_token"]) # No cached token — start interactive auth code flow - _LOGGER.debug("No cached token, initiating interactive auth code flow") + _LOGGER.info("No cached token, initiating interactive auth code flow") token = await self._interactive_flow(app, cache) return token @@ -186,7 +186,7 @@ async def _interactive_flow( raise AuthenticationError(f"Token exchange failed: {error} — {description}") await asyncio.to_thread(self._save_cache, cache) - _LOGGER.debug("Authentication successful, token acquired") + _LOGGER.info("Authentication successful, token acquired") return str(result["access_token"]) @staticmethod diff --git a/src/flameconnect/b2c_login.py b/src/flameconnect/b2c_login.py index df98129..b1f21ef 100644 --- a/src/flameconnect/b2c_login.py +++ b/src/flameconnect/b2c_login.py @@ -15,6 +15,7 @@ import aiohttp import yarl +from flameconnect._http_logging import log_request, log_response from flameconnect.const import CLIENT_ID from flameconnect.exceptions import AuthenticationError @@ -114,43 +115,6 @@ def _build_cookie_header( return "; ".join(f"{m.key}={m.value}" for m in filtered.values()) -def _log_request( - method: str, - url: str, - *, - headers: dict[str, str] | None = None, - data: dict[str, str] | None = None, - params: dict[str, str] | None = None, -) -> None: - """Log an outgoing HTTP request at DEBUG level.""" - _LOGGER.debug(">>> %s %s", method, url) - if params: - _LOGGER.debug(">>> params: %s", params) - if headers: - _LOGGER.debug(">>> headers: %s", headers) - if data: - safe = {k: ("***" if k == "password" else v) for k, v in data.items()} - _LOGGER.debug(">>> body: %s", safe) - - -def _log_response( - resp: aiohttp.ClientResponse, - body: str | None = None, -) -> None: - """Log an incoming HTTP response at DEBUG level.""" - _LOGGER.debug( - "<<< %s %s", - resp.status, - resp.url, - ) - _LOGGER.debug("<<< headers: %s", dict(resp.headers)) - if body is not None: - preview = body[:2000] - if len(body) > 2000: - preview += f"... ({len(body)} bytes total)" - _LOGGER.debug("<<< body: %s", preview) - - async def b2c_login_with_credentials(auth_uri: str, email: str, password: str) -> str: """Submit credentials directly to Azure AD B2C and return the redirect URL. @@ -179,11 +143,11 @@ async def b2c_login_with_credentials(auth_uri: str, email: str, password: str) - cookie_jar=jar, ) as session: # Step 1: GET the auth URI, follow redirects to B2C login page - _log_request("GET", auth_uri) + log_request(_LOGGER, "GET", auth_uri) async with session.get(auth_uri, allow_redirects=True) as resp: login_html = await resp.text() page_url = str(resp.url) - _log_response(resp, login_html) + log_response(_LOGGER, resp, login_html) if resp.status != 200: raise AuthenticationError( f"B2C login page returned HTTP {resp.status}" @@ -221,7 +185,8 @@ async def b2c_login_with_credentials(auth_uri: str, email: str, password: str) - cookie_header = _build_cookie_header(jar, fields.post_url) post_headers["Cookie"] = cookie_header _LOGGER.debug(">>> cookies: %s", cookie_header[:200]) - _log_request( + log_request( + _LOGGER, "POST", fields.post_url, headers=post_headers, @@ -242,7 +207,7 @@ async def b2c_login_with_credentials(auth_uri: str, email: str, password: str) - allow_redirects=False, ) as resp: body = await resp.text() - _log_response(resp, body) + log_response(_LOGGER, resp, body) if resp.status != 200: raise AuthenticationError( f"Credential submission returned HTTP {resp.status}" @@ -289,14 +254,14 @@ async def b2c_login_with_credentials(auth_uri: str, email: str, password: str) - "Cookie": cookie_header, } for _ in range(20): # max redirect hops - _log_request("GET", next_url) + log_request(_LOGGER, "GET", next_url) async with raw_session.get( yarl.URL(next_url, encoded=True), headers=confirmed_headers, allow_redirects=False, ) as resp: resp_body = await resp.text() - _log_response(resp, resp_body) + log_response(_LOGGER, resp, resp_body) if resp.status in (301, 302, 303, 307, 308): location = resp.headers.get("Location", "") if not location: diff --git a/src/flameconnect/cli.py b/src/flameconnect/cli.py index 93c5f8f..52c9925 100644 --- a/src/flameconnect/cli.py +++ b/src/flameconnect/cli.py @@ -695,7 +695,7 @@ async def _set_heat_status( } -async def cmd_tui(*, verbose: bool = False) -> None: +async def cmd_tui(*, log_level: int = logging.WARNING) -> None: """Launch the TUI, showing install message if missing.""" try: from flameconnect.tui import run_tui @@ -703,7 +703,7 @@ async def cmd_tui(*, verbose: bool = False) -> None: print("The TUI requires the 'tui' extra. Run with:") print(" uv tool run flameconnect[tui]") sys.exit(1) - await run_tui(verbose=verbose) + await run_tui(log_level=log_level) # --------------------------------------------------------------------------- @@ -720,11 +720,17 @@ def build_parser() -> argparse.ArgumentParser: " via the Flame Connect cloud API" ), ) - parser.add_argument( + verbosity = parser.add_mutually_exclusive_group() + verbosity.add_argument( "-v", "--verbose", action="store_true", - help="Enable debug logging", + help="Enable verbose logging", + ) + verbosity.add_argument( + "--debug", + action="store_true", + help="Enable verbose logging including HTTP requests and responses", ) subparsers = parser.add_subparsers(dest="command") @@ -846,17 +852,24 @@ async def _cli_auth_prompt(auth_uri: str, redirect_uri: str) -> str: async def async_main(args: argparse.Namespace) -> None: """Run the appropriate subcommand.""" + log_level = ( + logging.DEBUG + if args.debug + else logging.INFO + if args.verbose + else logging.WARNING + ) if args.command is None: try: from flameconnect.tui import run_tui except ImportError: build_parser().print_help() return - await run_tui(verbose=args.verbose) + await run_tui(log_level=log_level) return if args.command == "tui": - await cmd_tui(verbose=args.verbose) + await cmd_tui(log_level=log_level) return auth = MsalAuth(prompt_callback=_cli_auth_prompt) @@ -889,6 +902,12 @@ def main() -> None: parser = build_parser() args = parser.parse_args() logging.basicConfig( - level=logging.DEBUG if args.verbose else logging.WARNING, + level=( + logging.DEBUG + if args.debug + else logging.INFO + if args.verbose + else logging.WARNING + ), ) asyncio.run(async_main(args)) diff --git a/src/flameconnect/client.py b/src/flameconnect/client.py index 462978e..f944d94 100644 --- a/src/flameconnect/client.py +++ b/src/flameconnect/client.py @@ -3,6 +3,7 @@ from __future__ import annotations import base64 +import json as _json import logging from dataclasses import replace from typing import TYPE_CHECKING, Any, Literal, TypedDict @@ -10,6 +11,7 @@ import aiohttp +from flameconnect._http_logging import log_request, log_response from flameconnect.const import ( API_BASE, DEFAULT_HEADERS, @@ -191,16 +193,19 @@ async def _request( **DEFAULT_HEADERS, } + log_request(_LOGGER, method, url, headers=headers, data=json) + async with self._session.request( method, url, headers=headers, json=json ) as response: - _LOGGER.debug("%s %s -> %s", method, url, response.status) + body_text = await response.text() + log_response(_LOGGER, response, body_text) + _LOGGER.info("%s %s -> %s", method, url, response.status) if response.status < 200 or response.status >= 300: - text = await response.text() - raise ApiError(response.status, text) + raise ApiError(response.status, body_text) - result: Any = await response.json() + result: Any = _json.loads(body_text) return result # ------------------------------------------------------------------ diff --git a/src/flameconnect/tui/app.py b/src/flameconnect/tui/app.py index 31ab344..787ba16 100644 --- a/src/flameconnect/tui/app.py +++ b/src/flameconnect/tui/app.py @@ -906,15 +906,14 @@ def action_toggle_temp_unit(self) -> None: ) -async def run_tui(*, verbose: bool = False) -> None: +async def run_tui(*, log_level: int = logging.WARNING) -> None: """Launch the Flame Connect TUI dashboard. Creates an authenticated client and runs the Textual application. The client session is managed via an async context manager. Args: - verbose: When True, set the flameconnect logger to DEBUG so that - all log messages appear in the TUI messages panel. + log_level: The logging level for the flameconnect logger (default WARNING). """ import asyncio @@ -944,11 +943,9 @@ async def _tui_auth_prompt(auth_uri: str, redirect_uri: str) -> str: root_logger.removeHandler(handler) saved_handlers.append(handler) - # Only promote to DEBUG when the user passed -v/--verbose. fc_logger = logging.getLogger("flameconnect") prev_level = fc_logger.level - if verbose: - fc_logger.setLevel(logging.DEBUG) + fc_logger.setLevel(log_level) auth = MsalAuth(prompt_callback=_tui_auth_prompt) try: diff --git a/tests/test_b2c_login.py b/tests/test_b2c_login.py index 3131d52..4358a9b 100644 --- a/tests/test_b2c_login.py +++ b/tests/test_b2c_login.py @@ -12,17 +12,18 @@ import yarl from multidict import CIMultiDict +from flameconnect._http_logging import log_request, log_response from flameconnect.b2c_login import ( _B2C_POLICY, _build_cookie_header, _extract_base_path, - _log_request, - _log_response, _parse_login_page, b2c_login_with_credentials, ) from flameconnect.exceptions import AuthenticationError +_LOGGER = logging.getLogger("flameconnect.b2c_login") + # ------------------------------------------------------------------- # Sample B2C HTML used by tests # ------------------------------------------------------------------- @@ -214,12 +215,13 @@ class TestLogRequest: def test_basic_log(self, caplog): """Basic GET log includes method and URL.""" with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_request("GET", "https://example.com/api") + log_request(_LOGGER, "GET", "https://example.com/api") assert ">>> GET https://example.com/api" in caplog.text def test_params_logged(self, caplog): with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_request( + log_request( + _LOGGER, "GET", "https://example.com", params={"k": "v"}, @@ -229,7 +231,8 @@ def test_params_logged(self, caplog): def test_headers_logged(self, caplog): with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_request( + log_request( + _LOGGER, "GET", "https://example.com", headers={"Auth": "Bearer tok"}, @@ -240,7 +243,8 @@ def test_headers_logged(self, caplog): def test_data_logged_with_password_masked(self, caplog): """Password values are masked as '***'.""" with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_request( + log_request( + _LOGGER, "POST", "https://example.com", data={ @@ -256,7 +260,7 @@ def test_data_logged_with_password_masked(self, caplog): def test_no_params_no_extra_log(self, caplog): """Without params/headers/data, only method+URL logged.""" with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_request("GET", "https://example.com") + log_request(_LOGGER, "GET", "https://example.com") assert "params" not in caplog.text assert "headers" not in caplog.text assert "body" not in caplog.text @@ -280,14 +284,14 @@ def _make_resp(self, status=200, url="https://example.com"): def test_basic_response_logged(self, caplog): resp = self._make_resp(status=200) with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_response(resp) + log_response(_LOGGER, resp) assert "200" in caplog.text assert "headers" in caplog.text.lower() def test_body_logged(self, caplog): resp = self._make_resp() with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_response(resp, "Hello body") + log_response(_LOGGER, resp, "Hello body") # Check exact log record message (kills "<<< body: %s" → "XX...") body_records = [r for r in caplog.records if "body" in r.getMessage().lower()] assert body_records @@ -298,7 +302,7 @@ def test_long_body_truncated(self, caplog): resp = self._make_resp() long_body = "x" * 3000 with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_response(resp, long_body) + log_response(_LOGGER, resp, long_body) assert "bytes total" in caplog.text assert "3000" in caplog.text # Body preview includes first 2000 chars (kills += → = mutant) @@ -308,21 +312,21 @@ def test_body_exactly_2000_no_truncation(self, caplog): resp = self._make_resp() body_2000 = "y" * 2000 with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_response(resp, body_2000) + log_response(_LOGGER, resp, body_2000) assert "bytes total" not in caplog.text def test_body_2001_truncated(self, caplog): resp = self._make_resp() body_2001 = "z" * 2001 with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_response(resp, body_2001) + log_response(_LOGGER, resp, body_2001) assert "bytes total" in caplog.text assert "2001" in caplog.text def test_none_body_no_body_log(self, caplog): resp = self._make_resp() with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_response(resp, None) + log_response(_LOGGER, resp, None) # Should not have body line (None means no body log) # But status and headers are always logged assert "200" in caplog.text @@ -1199,7 +1203,7 @@ class TestLogRequestMutants: def test_exact_prefix_format(self, caplog): """Kill mutant 7: '>>> %s %s' -> 'XX>>> %s %sXX'.""" with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_request("GET", "https://example.com/api") + log_request(_LOGGER, "GET", "https://example.com/api") assert ">>> GET https://example.com/api" in caplog.text # Ensure no XX corruption assert "XX" not in caplog.text @@ -1207,21 +1211,26 @@ def test_exact_prefix_format(self, caplog): def test_params_exact_prefix(self, caplog): """Mutant 13: params line prefix mutated.""" with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_request("GET", "https://example.com", params={"k": "v"}) + log_request(_LOGGER, "GET", "https://example.com", params={"k": "v"}) assert ">>> params:" in caplog.text assert "XX" not in caplog.text def test_headers_exact_prefix(self, caplog): """Mutant 19: headers line prefix mutated.""" with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_request("GET", "https://example.com", headers={"H": "v"}) + log_request(_LOGGER, "GET", "https://example.com", headers={"H": "v"}) assert ">>> headers:" in caplog.text assert "XX" not in caplog.text def test_password_mask_exact(self, caplog): """Mutant 22: '***' -> 'XX***XX'.""" with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_request("POST", "https://example.com", data={"password": "secret"}) + log_request( + _LOGGER, + "POST", + "https://example.com", + data={"password": "secret"}, + ) # The masked value should be exactly '***', not 'XX***XX' assert "'***'" in caplog.text or '"***"' in caplog.text assert "XX***XX" not in caplog.text @@ -1229,7 +1238,7 @@ def test_password_mask_exact(self, caplog): def test_body_exact_prefix(self, caplog): """Mutant 30: body line prefix mutated.""" with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_request("POST", "https://example.com", data={"k": "v"}) + log_request(_LOGGER, "POST", "https://example.com", data={"k": "v"}) assert ">>> body:" in caplog.text assert "XX" not in caplog.text @@ -1251,14 +1260,14 @@ def test_url_logged_not_none(self, caplog): """Mutant 3: resp.url -> None.""" resp = self._make_resp(url="https://specific.example.com/path") with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_response(resp) + log_response(_LOGGER, resp) assert "https://specific.example.com/path" in caplog.text def test_exact_status_line_prefix(self, caplog): """Mutant 7: '<<< %s %s' -> 'XX<<< %s %sXX'.""" resp = self._make_resp(status=201) with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_response(resp) + log_response(_LOGGER, resp) assert "<<< 201" in caplog.text assert "XX" not in caplog.text @@ -1266,14 +1275,14 @@ def test_headers_logged_as_dict(self, caplog): """Mutant 10: dict(resp.headers) -> None.""" resp = self._make_resp() with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_response(resp) + log_response(_LOGGER, resp) assert "X-Test" in caplog.text def test_headers_not_removed(self, caplog): """Mutant 12: removes dict(resp.headers) arg entirely.""" resp = self._make_resp() with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_response(resp) + log_response(_LOGGER, resp) # The dict argument should be present and contain headers assert "yes" in caplog.text @@ -1281,7 +1290,7 @@ def test_headers_line_exact_prefix(self, caplog): """Mutant 13: '<<< headers: %s' -> 'XX<<< headers: %sXX'.""" resp = self._make_resp() with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_response(resp) + log_response(_LOGGER, resp) assert "<<< headers:" in caplog.text assert "XX" not in caplog.text @@ -1298,7 +1307,7 @@ def test_body_preview_exact_length(self, caplog): # Use a unique marker at position 2001 that won't appear elsewhere body = "a" * 2000 + "\x07" # 2001 chars, \x07 (BEL) is the extra char with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_response(resp, body) + log_response(_LOGGER, resp, body) # With correct code: body[:2000] means preview is 'a' * 2000 # and '\x07' should NOT be in the preview # With mutant code: body[:2001] means '\x07' IS in the preview @@ -1311,7 +1320,7 @@ def test_body_logged_with_body_prefix(self, caplog): """Mutants 21, 25, 27 -- various format string mutations.""" resp = self._make_resp() with caplog.at_level(logging.DEBUG, "flameconnect"): - _log_response(resp, "test body content") + log_response(_LOGGER, resp, "test body content") assert "<<< body:" in caplog.text assert "test body content" in caplog.text @@ -1869,7 +1878,7 @@ async def test_log_request_get_url(self, caplog): assert AUTH_URI in caplog.text async def test_log_response_body_passed(self, caplog): - """Mutants 26, 28: _log_response(resp, login_html) -> (resp, None) or (resp,). + """Mutants 26, 28: log_response(resp, login_html) mutations. When body is None, _log_response skips body logging. With the real login_html, body should appear in logs. @@ -1898,7 +1907,7 @@ async def test_parsed_debug_has_ellipsis(self, caplog): assert "XX...XX" not in caplog.text async def test_log_request_post_method(self, caplog): - """Mutants 118 (None), 127 ('post'): _log_request('POST', ...) mutations.""" + """Mutants 118, 127: log_request 'POST' mutations.""" await self._run_flow_with_logging(caplog) assert ">>> POST" in caplog.text @@ -1909,7 +1918,7 @@ async def test_cookies_debug_line(self, caplog): assert "XX" not in caplog.text.replace("XMLHttpRequest", "") async def test_log_response_post_body(self, caplog): - """Mutants 155, 157: _log_response(resp, body) -> (resp, None) or (resp,).""" + """Mutants 155, 157: log_response(resp, body) mutations.""" await self._run_flow_with_logging(caplog) # The POST response body is '{"status":"200"}', it should be logged assert '"status":"200"' in caplog.text @@ -2308,8 +2317,8 @@ class TestLogNoneDetection: """Kill logging mutants M11 and M12 by detecting 'None' in log output.""" async def test_no_none_in_log_method_or_url(self, caplog): - """M11: _log_request(None, auth_uri) — logs '>>> None ...' - M12: _log_request('GET', None) — logs '>>> GET None' + """M11: log_request(_LOGGER,None, auth_uri) — logs '>>> None ...' + M12: log_request(_LOGGER,'GET', None) — logs '>>> GET None' Verify that no log line contains 'None' where a method or URL should be. """ diff --git a/tests/test_cli_commands.py b/tests/test_cli_commands.py index d4757a1..6177f08 100644 --- a/tests/test_cli_commands.py +++ b/tests/test_cli_commands.py @@ -3,6 +3,7 @@ from __future__ import annotations import argparse +import logging import sys from unittest.mock import AsyncMock, MagicMock, patch @@ -1347,14 +1348,34 @@ def test_verbose_flag_help(self): """--verbose flag has help text.""" parser = build_parser() for action in parser._actions: + if isinstance(action, argparse._MutuallyExclusiveGroup): + for sub_action in action._group_actions: + if "--verbose" in getattr(sub_action, "option_strings", []): + assert sub_action.help is not None + assert "logging" in sub_action.help.lower() + return if "--verbose" in getattr(action, "option_strings", []): assert action.help is not None - assert ( - "debug" in action.help.lower() or "logging" in action.help.lower() - ) + assert "logging" in action.help.lower() return raise AssertionError("--verbose action not found") + def test_debug_flag_help(self): + """--debug flag has help text.""" + parser = build_parser() + for action in parser._actions: + if isinstance(action, argparse._MutuallyExclusiveGroup): + for sub_action in action._group_actions: + if "--debug" in getattr(sub_action, "option_strings", []): + assert sub_action.help is not None + assert "http" in sub_action.help.lower() + return + if "--debug" in getattr(action, "option_strings", []): + assert action.help is not None + assert "http" in action.help.lower() + return + raise AssertionError("--debug action not found") + def test_parse_list(self): parser = build_parser() args = parser.parse_args(["list"]) @@ -1395,11 +1416,24 @@ def test_parse_verbose(self): parser = build_parser() args = parser.parse_args(["-v", "list"]) assert args.verbose is True + assert args.debug is False + + def test_parse_debug(self): + parser = build_parser() + args = parser.parse_args(["--debug", "list"]) + assert args.debug is True + assert args.verbose is False def test_parse_no_verbose(self): parser = build_parser() args = parser.parse_args(["list"]) assert args.verbose is False + assert args.debug is False + + def test_verbose_debug_mutually_exclusive(self): + parser = build_parser() + with pytest.raises(SystemExit): + parser.parse_args(["--verbose", "--debug", "list"]) def test_no_command(self): parser = build_parser() @@ -1416,13 +1450,13 @@ class TestAsyncMain: """Tests for async_main() dispatch.""" async def test_tui_command(self): - args = argparse.Namespace(command="tui", verbose=False) + args = argparse.Namespace(command="tui", verbose=False, debug=False) with patch("flameconnect.cli.cmd_tui", new_callable=AsyncMock) as mock_tui: await async_main(args) - mock_tui.assert_awaited_once_with(verbose=False) + mock_tui.assert_awaited_once_with(log_level=logging.WARNING) async def test_none_command_prints_help_without_tui(self, capsys, monkeypatch): - args = argparse.Namespace(command=None, verbose=False) + args = argparse.Namespace(command=None, verbose=False, debug=False) import builtins real_import = builtins.__import__ @@ -1440,16 +1474,16 @@ def _guarded_import(name, *a, **kw): # type: ignore[no-untyped-def] assert "usage" in captured.out.lower() async def test_none_command_launches_tui_with_textual(self): - args = argparse.Namespace(command=None, verbose=False) + args = argparse.Namespace(command=None, verbose=False, debug=False) mock_run_tui = AsyncMock() mock_module = MagicMock() mock_module.run_tui = mock_run_tui with patch.dict("sys.modules", {"flameconnect.tui": mock_module}): await async_main(args) - mock_run_tui.assert_awaited_once_with(verbose=False) + mock_run_tui.assert_awaited_once_with(log_level=logging.WARNING) async def test_list_command(self): - args = argparse.Namespace(command="list", verbose=False) + args = argparse.Namespace(command="list", verbose=False, debug=False) mock_client = AsyncMock() mock_client.get_fires.return_value = [] mock_client.__aenter__ = AsyncMock(return_value=mock_client) @@ -1463,7 +1497,12 @@ async def test_list_command(self): mock_client.get_fires.assert_awaited_once() async def test_status_command(self): - args = argparse.Namespace(command="status", fire_id=FIRE_ID, verbose=False) + args = argparse.Namespace( + command="status", + fire_id=FIRE_ID, + verbose=False, + debug=False, + ) mock_client = AsyncMock() overview = FireOverview(fire=_make_fire(), parameters=[]) mock_client.get_fire_overview.return_value = overview @@ -1478,7 +1517,12 @@ async def test_status_command(self): mock_client.get_fire_overview.assert_awaited_once_with(FIRE_ID) async def test_on_command(self): - args = argparse.Namespace(command="on", fire_id=FIRE_ID, verbose=False) + args = argparse.Namespace( + command="on", + fire_id=FIRE_ID, + verbose=False, + debug=False, + ) mock_client = AsyncMock() mock_client.__aenter__ = AsyncMock(return_value=mock_client) mock_client.__aexit__ = AsyncMock(return_value=False) @@ -1491,7 +1535,12 @@ async def test_on_command(self): mock_client.turn_on.assert_awaited_once_with(FIRE_ID) async def test_off_command(self): - args = argparse.Namespace(command="off", fire_id=FIRE_ID, verbose=False) + args = argparse.Namespace( + command="off", + fire_id=FIRE_ID, + verbose=False, + debug=False, + ) mock_client = AsyncMock() mock_client.__aenter__ = AsyncMock(return_value=mock_client) mock_client.__aexit__ = AsyncMock(return_value=False) @@ -1510,6 +1559,7 @@ async def test_set_command(self): param="temp-unit", value="celsius", verbose=False, + debug=False, ) mock_client = AsyncMock() mock_client.__aenter__ = AsyncMock(return_value=mock_client) @@ -1523,10 +1573,16 @@ async def test_set_command(self): mock_client.write_parameters.assert_awaited_once() async def test_tui_verbose(self): - args = argparse.Namespace(command="tui", verbose=True) + args = argparse.Namespace(command="tui", verbose=True, debug=False) with patch("flameconnect.cli.cmd_tui", new_callable=AsyncMock) as mock_tui: await async_main(args) - mock_tui.assert_awaited_once_with(verbose=True) + mock_tui.assert_awaited_once_with(log_level=logging.INFO) + + async def test_tui_debug(self): + args = argparse.Namespace(command="tui", verbose=False, debug=True) + with patch("flameconnect.cli.cmd_tui", new_callable=AsyncMock) as mock_tui: + await async_main(args) + mock_tui.assert_awaited_once_with(log_level=logging.DEBUG) # =================================================================== @@ -1545,7 +1601,7 @@ def test_main_calls_async_main(self): patch("flameconnect.cli.async_main", new=mock_async_main), ): mock_parser = MagicMock() - mock_args = argparse.Namespace(command="list", verbose=False) + mock_args = argparse.Namespace(command="list", verbose=False, debug=False) mock_parser.parse_args.return_value = mock_args mock_parser_fn.return_value = mock_parser @@ -1566,15 +1622,16 @@ def test_main_verbose_logging(self): import logging as real_logging mock_parser = MagicMock() - mock_args = argparse.Namespace(command="list", verbose=True) + mock_args = argparse.Namespace(command="list", verbose=True, debug=False) mock_parser.parse_args.return_value = mock_args mock_parser_fn.return_value = mock_parser mock_logging.DEBUG = real_logging.DEBUG + mock_logging.INFO = real_logging.INFO mock_logging.WARNING = real_logging.WARNING main() - mock_logging.basicConfig.assert_called_once_with(level=real_logging.DEBUG) + mock_logging.basicConfig.assert_called_once_with(level=real_logging.INFO) def test_main_no_verbose_logging(self): with ( @@ -1586,16 +1643,38 @@ def test_main_no_verbose_logging(self): import logging as real_logging mock_parser = MagicMock() - mock_args = argparse.Namespace(command="list", verbose=False) + mock_args = argparse.Namespace(command="list", verbose=False, debug=False) mock_parser.parse_args.return_value = mock_args mock_parser_fn.return_value = mock_parser mock_logging.DEBUG = real_logging.DEBUG + mock_logging.INFO = real_logging.INFO mock_logging.WARNING = real_logging.WARNING main() mock_logging.basicConfig.assert_called_once_with(level=real_logging.WARNING) + def test_main_debug_logging(self): + with ( + patch("flameconnect.cli.build_parser") as mock_parser_fn, + patch("flameconnect.cli.asyncio"), + patch("flameconnect.cli.async_main", new=MagicMock()), + patch("flameconnect.cli.logging") as mock_logging, + ): + import logging as real_logging + + mock_parser = MagicMock() + mock_args = argparse.Namespace(command="list", verbose=False, debug=True) + mock_parser.parse_args.return_value = mock_args + mock_parser_fn.return_value = mock_parser + mock_logging.DEBUG = real_logging.DEBUG + mock_logging.INFO = real_logging.INFO + mock_logging.WARNING = real_logging.WARNING + + main() + + mock_logging.basicConfig.assert_called_once_with(level=real_logging.DEBUG) + # =================================================================== # cmd_tui tests @@ -1622,8 +1701,8 @@ async def test_tui_runs(self): mock_module.run_tui = mock_run_tui with patch.dict("sys.modules", {"flameconnect.tui": mock_module}): - await cmd_tui(verbose=True) - mock_run_tui.assert_awaited_once_with(verbose=True) + await cmd_tui(log_level=logging.DEBUG) + mock_run_tui.assert_awaited_once_with(log_level=logging.DEBUG) # =================================================================== diff --git a/tests/test_client.py b/tests/test_client.py index 034f769..d071665 100644 --- a/tests/test_client.py +++ b/tests/test_client.py @@ -1438,11 +1438,13 @@ async def test_request_logs_method_url_status(self, mock_api, token_auth, caplog async with FlameConnectClient(token_auth) as client: await client.get_fires() - # Find the debug message from _request + # Find the info-level log that contains method, URL, and status found = [ r for r in caplog.records - if r.name == "flameconnect.client" and "GET" in r.message + if r.name == "flameconnect.client" + and r.levelno == logging.INFO + and "GET" in r.message ] assert len(found) >= 1 msg = found[0].message @@ -1534,21 +1536,21 @@ class TestRequestDebugLog: """ async def test_request_debug_log_format(self, mock_api, token_auth, caplog): - """Debug log must start with method name, not 'XX'.""" + """Request summary log must start with method name, not 'XX'.""" url = f"{API_BASE}/api/Fires/GetFires" mock_api.get(url, payload=[]) - with caplog.at_level(logging.DEBUG, logger="flameconnect.client"): + with caplog.at_level(logging.INFO, logger="flameconnect.client"): async with FlameConnectClient(token_auth) as client: await client.get_fires() - debug_msgs = [ + info_msgs = [ r for r in caplog.records - if r.name == "flameconnect.client" and r.levelno == logging.DEBUG + if r.name == "flameconnect.client" and r.levelno == logging.INFO ] - assert len(debug_msgs) >= 1 - msg = debug_msgs[0].getMessage() + assert len(info_msgs) >= 1 + msg = info_msgs[0].getMessage() assert msg.startswith("GET ") assert "XX" not in msg diff --git a/tests/test_http_logging.py b/tests/test_http_logging.py new file mode 100644 index 0000000..d2c00ac --- /dev/null +++ b/tests/test_http_logging.py @@ -0,0 +1,256 @@ +"""Tests for the shared HTTP logging helpers.""" + +from __future__ import annotations + +import logging +from typing import Any +from unittest.mock import MagicMock + +import aiohttp +import pytest +from aioresponses import aioresponses as aioresponses_mock +from yarl import URL + +from flameconnect._http_logging import ( + log_request, + log_response, + redact_body, + redact_headers, +) +from flameconnect.auth import TokenAuth +from flameconnect.client import FlameConnectClient +from flameconnect.const import API_BASE + +# --------------------------------------------------------------------------- +# redact_headers +# --------------------------------------------------------------------------- + + +class TestRedactHeaders: + """Tests for redact_headers.""" + + def test_authorization_with_scheme(self) -> None: + assert redact_headers({"Authorization": "Bearer my-token"}) == { + "Authorization": "Bearer ***" + } + + def test_authorization_without_scheme(self) -> None: + assert redact_headers({"Authorization": "my-token"}) == {"Authorization": "***"} + + def test_cookie_redacted(self) -> None: + assert redact_headers({"Cookie": "session=abc"}) == {"Cookie": "***"} + + def test_set_cookie_redacted(self) -> None: + assert redact_headers({"Set-Cookie": "session=abc"}) == {"Set-Cookie": "***"} + + def test_x_csrf_token_redacted(self) -> None: + assert redact_headers({"X-CSRF-TOKEN": "tok123"}) == {"X-CSRF-TOKEN": "***"} + + def test_case_insensitivity(self) -> None: + for key in ("AUTHORIZATION", "authorization", "Authorization"): + result = redact_headers({key: "Bearer secret"}) + assert result[key] == "Bearer ***" + + def test_non_sensitive_passes_through(self) -> None: + assert redact_headers({"Content-Type": "application/json"}) == { + "Content-Type": "application/json" + } + + def test_empty_dict(self) -> None: + assert redact_headers({}) == {} + + +# --------------------------------------------------------------------------- +# redact_body +# --------------------------------------------------------------------------- + + +class TestRedactBody: + """Tests for redact_body.""" + + def test_password_redacted(self) -> None: + assert redact_body({"password": "s3cret", "user": "bob"}) == { + "password": "***", + "user": "bob", + } + + def test_password_case_insensitive(self) -> None: + for key in ("Password", "PASSWORD", "password"): + result = redact_body({key: "s3cret"}) + assert result[key] == "***" + + def test_other_keys_unchanged(self) -> None: + assert redact_body({"email": "a@b.com"}) == {"email": "a@b.com"} + + def test_empty_dict(self) -> None: + assert redact_body({}) == {} + + +# --------------------------------------------------------------------------- +# log_request +# --------------------------------------------------------------------------- + + +class TestLogRequest: + """Tests for log_request.""" + + def test_logs_method_and_url(self) -> None: + logger = MagicMock(spec=logging.Logger) + log_request(logger, "GET", "https://example.com/api") + logger.debug.assert_any_call(">>> %s %s", "GET", "https://example.com/api") + + def test_logs_redacted_headers(self) -> None: + logger = MagicMock(spec=logging.Logger) + log_request( + logger, + "POST", + "https://example.com", + headers={"Authorization": "Bearer tok", "Accept": "text/html"}, + ) + logger.debug.assert_any_call( + ">>> headers: %s", + {"Authorization": "Bearer ***", "Accept": "text/html"}, + ) + + def test_logs_redacted_body(self) -> None: + logger = MagicMock(spec=logging.Logger) + log_request( + logger, + "POST", + "https://example.com", + data={"password": "secret", "user": "alice"}, + ) + logger.debug.assert_any_call( + ">>> body: %s", + {"password": "***", "user": "alice"}, + ) + + def test_logs_params(self) -> None: + logger = MagicMock(spec=logging.Logger) + log_request( + logger, + "GET", + "https://example.com", + params={"q": "fire"}, + ) + logger.debug.assert_any_call(">>> params: %s", {"q": "fire"}) + + def test_no_headers_body_params_when_none(self) -> None: + logger = MagicMock(spec=logging.Logger) + log_request(logger, "GET", "https://example.com") + # Only one debug call: the method/url line + assert logger.debug.call_count == 1 + + +# --------------------------------------------------------------------------- +# log_response +# --------------------------------------------------------------------------- + + +class TestLogResponse: + """Tests for log_response.""" + + def _make_response( + self, + status: int = 200, + url: str = "https://example.com", + headers: dict[str, str] | None = None, + ) -> MagicMock: + resp = MagicMock(spec=aiohttp.ClientResponse) + resp.status = status + resp.url = URL(url) + resp.headers = headers or {"Content-Type": "text/html"} + return resp + + def test_logs_status_and_url(self) -> None: + logger = MagicMock(spec=logging.Logger) + resp = self._make_response(200, "https://example.com/path") + log_response(logger, resp) + logger.debug.assert_any_call("<<< %s %s", 200, URL("https://example.com/path")) + + def test_logs_redacted_response_headers(self) -> None: + logger = MagicMock(spec=logging.Logger) + resp = self._make_response(headers={"Set-Cookie": "x=1"}) + log_response(logger, resp) + logger.debug.assert_any_call("<<< headers: %s", {"Set-Cookie": "***"}) + + def test_logs_body(self) -> None: + logger = MagicMock(spec=logging.Logger) + resp = self._make_response() + log_response(logger, resp, body="hello world") + logger.debug.assert_any_call("<<< body: %s", "hello world") + + def test_truncates_long_body(self) -> None: + logger = MagicMock(spec=logging.Logger) + resp = self._make_response() + long_body = "x" * 3000 + log_response(logger, resp, body=long_body) + expected = "x" * 2000 + "... (3000 bytes total)" + logger.debug.assert_any_call("<<< body: %s", expected) + + def test_no_body_when_none(self) -> None: + logger = MagicMock(spec=logging.Logger) + resp = self._make_response() + log_response(logger, resp, body=None) + # Two debug calls: status/url + headers, but no body + assert logger.debug.call_count == 2 + + +# --------------------------------------------------------------------------- +# client.py integration tests +# --------------------------------------------------------------------------- + + +class TestClientHttpLogging: + """Verify _request in FlameConnectClient uses shared logging helpers.""" + + @pytest.fixture() + def mock_api(self) -> Any: + with aioresponses_mock() as m: + yield m + + @pytest.fixture() + def token_auth(self) -> TokenAuth: + return TokenAuth("test-token-123") + + async def test_request_logs_debug_headers_and_body( + self, + mock_api: Any, + token_auth: TokenAuth, + caplog: pytest.LogCaptureFixture, + ) -> None: + url = f"{API_BASE}/api/Fires/GetFires" + mock_api.get(url, payload=[{"id": 1}]) + + with caplog.at_level(logging.DEBUG, logger="flameconnect.client"): + async with FlameConnectClient(token_auth) as client: + await client._request("GET", url) + + # Request headers should be logged (redacted) + assert any( + ">>> GET" in rec.message and url in rec.message for rec in caplog.records + ) + assert any(">>> headers:" in rec.message for rec in caplog.records) + # Response body should be logged + assert any("<<< body:" in rec.message for rec in caplog.records) + + async def test_request_redacts_bearer_token( + self, + mock_api: Any, + token_auth: TokenAuth, + caplog: pytest.LogCaptureFixture, + ) -> None: + url = f"{API_BASE}/api/Fires/GetFires" + mock_api.get(url, payload=[]) + + with caplog.at_level(logging.DEBUG, logger="flameconnect.client"): + async with FlameConnectClient(token_auth) as client: + await client._request("GET", url) + + header_logs = [ + rec.message for rec in caplog.records if ">>> headers:" in rec.message + ] + assert len(header_logs) >= 1 + # Token must be redacted + assert "Bearer ***" in header_logs[0] + assert "test-token-123" not in header_logs[0]