diff --git a/AGENTS.md b/AGENTS.md index 792fdf3d..f64aae2a 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -33,6 +33,7 @@ These three documents define the patterns this codebase already uses. Generating | `list_*` methods, pagination, iterator vs list, the `_list` helper | [`docs/ITERATORS.md`](docs/ITERATORS.md) | | Pydantic model conventions: `ConfigDict`, aliases, validators, relationships, exporting | [`docs/MODELS.md`](docs/MODELS.md) | | Resource service patterns: method shape, JSON:API envelopes, client wiring, examples | [`docs/RESOURCE.md`](docs/RESOURCE.md) | +| Logging: namespace, redaction, env-var setup, debug round-trip traces | [`docs/LOGGING.md`](docs/LOGGING.md) | Each doc ends with a checklist. Use those checklists; they encode the rules a reviewer will look for. @@ -75,6 +76,7 @@ These are mistakes a competent Python developer would make if they hadn't read t - **Don't add features beyond what was asked.** This codebase is approaching v1.0.0. Adding "while I'm here" refactors or speculative abstractions slows reviews and risks breaking the Ansible collection. - **Don't assume every successful response is `{"data": ...}`.** Check the docs/go-tfe/spec for each endpoint: some return a JSON:API envelope, some return a bare resource object, `204 No Content`, `null`, raw bytes, or a redirect to a blob URL. Add tests for non-standard shapes. - **Don't use bare `list[...]` annotations inside a resource class after defining `def list(...)`.** In class scope, mypy can resolve `list` to the method instead of the builtin. Use `builtins.list[...]`, `Sequence[...]`, or another unshadowed type. +- **Don't `print()` or use ad-hoc `logging.getLogger(__name__)` calls in library code.** The SDK has a structured logging framework — use `pytfe._logging.transport_logger` for HTTP traffic, or `pytfe._logging.logger` (the `pytfe` root) for higher-level events. Everything from that namespace is silent by default (NullHandler) and respects the user's `setup_logging()` or stdlib configuration. See [LOGGING.md](docs/LOGGING.md) for redaction rules — bearer tokens and `token`/`secret`/`password` keys are auto-redacted by `RoundTrip`, but only inside that formatter. Never `log.info(token)` directly. ## Known cross-dependencies you should not break diff --git a/README.md b/README.md index 2a507001..94728d15 100644 --- a/README.md +++ b/README.md @@ -93,10 +93,73 @@ A couple of things worth knowing: - The iterator is **single-use**. Once you've walked it, iterating again gives you nothing. Capture it with `list(...)` first if you need to reuse the result. - Filters and page size live on the `*ListOptions` model for each resource — e.g. `WorkspaceListOptions(search="prod", page_size=50)`. Pagination still happens transparently; `page_size` only controls how big each underlying API page is. +## Logging + +pyTFE integrates with Python's standard `logging` module and is **silent by default** — nothing is emitted unless you opt in. The library publishes two loggers: + +- `pytfe` — root namespace; rarely emits directly +- `pytfe.transport` — HTTP request/response and retry trace + +### Turn it on with an environment variable + +The quickest way is to set `PYTFE_LOG`: + +```bash +PYTFE_LOG=debug python my_script.py +``` + +`setup_logging()` is invoked automatically on package import, so the env var alone is enough — no code change required. Use the programmatic call only when you need to (re)apply env vars set after import (e.g. in a REPL or test): + +```python +import pytfe +pytfe.setup_logging() +``` + +Levels: `debug` shows every request/response, `info` shows retry decisions only. + +### Sample output + +``` +[2026-05-25 14:12:26 pytfe.transport DEBUG] +> GET /api/v2/organizations/acme/workspaces?page[number]=1&page[size]=100 +< 200 OK +< { +< "data": [ +< { "id": "ws-...", "type": "workspaces", ... } +< ] +< } +``` + +### Safe by default + +Bearer tokens and other credentials are redacted **before** they reach the logger: + +- Sensitive headers (`Authorization`, `Cookie`, anything containing `token` / `secret` / `password` / `api-key`) are replaced with `**REDACTED**`. Headers are off by default; even when you turn them on with `PYTFE_LOG_HEADERS=true`, redaction still applies. +- JSON bodies have sensitive keys (`token`, `access_token`, `refresh_token`, `secret`, `password`, `private_key`, `client_secret`) replaced recursively. +- Large bodies are truncated to `PYTFE_LOG_TRUNCATE_BYTES` (default `1024`). Long arrays are clipped with `"... (N additional elements)"`. +- Binary responses (state-version downloads, configuration-version tarballs, etc.) render as `[raw stream]` — the bytes are never decoded into the log. + +### Compose with your existing logging + +Because pyTFE uses stdlib `logging`, all the standard knobs work: + +```python +import logging + +# Just the HTTP traffic, at DEBUG +logging.getLogger("pytfe.transport").setLevel(logging.DEBUG) + +# Send pyTFE logs to your existing handler instead of stderr +logging.getLogger("pytfe").addHandler(my_json_handler) +``` + +For full details — environment variables, redaction guarantees, and how to add log statements to new SDK code — see [`docs/LOGGING.md`](./docs/LOGGING.md). + ## Documentation - API reference and guides (SDK): **coming soon** - Terraform Enterprise API: https://developer.hashicorp.com/terraform/enterprise/api-docs +- Internal reference: [`docs/ITERATORS.md`](./docs/ITERATORS.md), [`docs/MODELS.md`](./docs/MODELS.md), [`docs/RESOURCE.md`](./docs/RESOURCE.md), [`docs/LOGGING.md`](./docs/LOGGING.md) ## Examples diff --git a/docs/LOGGING.md b/docs/LOGGING.md new file mode 100644 index 00000000..3cb0fcab --- /dev/null +++ b/docs/LOGGING.md @@ -0,0 +1,150 @@ +# Logging in pyTFE + +Internal reference for the SDK's logging framework. Companion to [`ITERATORS.md`](ITERATORS.md), [`MODELS.md`](MODELS.md), [`RESOURCE.md`](RESOURCE.md). + +The framework is designed to be **silent by default** (library best practice — no logs unless the caller opts in), **integrated with stdlib `logging`** (so it composes with the user's existing setup), and **safe** (bearer tokens and other credentials are redacted before they ever reach a handler). + +## The one-line quickstart for users + +```bash +PYTFE_LOG=debug python my_script.py +``` + +`setup_logging()` is invoked automatically when the `pytfe` package is imported, so the env var is the entire user surface — no code change required. Programmatic equivalent (handy in tests or in REPLs where the env var was set after import): + +```python +import pytfe +pytfe.setup_logging() +``` + +`setup_logging()` is idempotent — calling it more than once is safe. + +That's it. Anything between `DEBUG`-level HTTP request/response traces and `INFO`-level retry decisions will show up on stderr with a per-line format like: + +``` +[2026-05-25 14:12:26 pytfe.transport DEBUG] +> GET /api/v2/organizations/acme/workspaces?page[number]=1&page[size]=100 +< 200 OK +< { +< "data": [ +< { "id": "ws-...", "type": "workspaces", ... } +< ] +< } +``` + +## Logger namespace + +| Logger | What it logs | +|---|---| +| `pytfe` | Root namespace; rarely emits directly. Use it to dial **everything** pytfe says up or down at once. | +| `pytfe.transport` | HTTP request/response (DEBUG), retry decisions (INFO), transport exceptions (DEBUG). The noisy one. | + +There is no `pytfe.resource.*` per-service logger. Resource methods do not log; if a caller needs visibility into "the SDK is calling `client.workspaces.read('ws-abc')'" they get it via the transport log right below it. + +Standard stdlib selectors apply: + +```python +import logging +logging.getLogger("pytfe").setLevel(logging.INFO) # everything +logging.getLogger("pytfe.transport").setLevel(logging.DEBUG) # just HTTP +``` + +## Configuration knobs + +The framework has three environment variables. All are optional. + +| Variable | Default | Effect | +|---|---|---| +| `PYTFE_LOG` | unset | `debug` or `info` (case-insensitive) configures stdlib `logging` for you. Anything else is ignored. | +| `PYTFE_LOG_HEADERS` | `false` | When truthy, include request/response headers in `RoundTrip` output. Sensitive ones are still redacted; this just turns on the `> * Header: value` lines at all. | +| `PYTFE_LOG_TRUNCATE_BYTES` | `1024` | Truncation budget for any single string in a logged body. Values below 96 are clamped up. | + +All three are read at call time, not at import — switching `PYTFE_LOG_HEADERS=true` in the middle of a long-running process takes effect on the next request. + +## Redaction guarantees + +The `RoundTrip` formatter (in [`src/pytfe/_logging.py`](../src/pytfe/_logging.py)) redacts before formatting, so the redacted value never reaches the logger: + +**Headers** — replaced with `**REDACTED**` when matched. Names matched case-insensitively: + +``` +authorization +cookie +set-cookie +proxy-authorization +x-tfc-task-signature +``` + +Plus any header whose name contains the substring `token`, `secret`, `password`, `api-key`, or `apikey`. + +**JSON bodies** — when the response body is JSON, these top-level *and nested* keys have their values replaced (case-insensitive key match): + +``` +token, access_token, refresh_token, +secret, password, +private_key, client_secret +``` + +This is structural: a value can be redacted even if it's deep inside an array of nested objects. **String values themselves are not scanned for tokens** — only the keys are matched. If you stuff a bearer token into a field named `"description"`, it will appear in the log. + +The `**REDACTED**` constant is exported from `pytfe._logging` if you ever need to assert on it in a test. + +## Truncation behavior + +Bodies are formatted, not echoed: + +- JSON arrays beyond the budget are clipped with `"... (N additional elements)"`. +- JSON string values longer than the per-string budget are clipped with `"... (N more bytes)"`. +- Non-JSON bodies are shown verbatim (after the same per-string truncation). +- Binary bodies (state-version downloads, CV tarballs, anything with a non-text/non-JSON `Content-Type`) are rendered as `[raw stream]` — the body is not decoded or formatted. + +This keeps a `--list` over a 10,000-workspace organization to one screen of log output instead of 10MB. + +## How the transport uses it + +[`src/pytfe/_http.py`](../src/pytfe/_http.py) emits: + +| Event | Logger | Level | Cost when disabled | +|---|---|---|---| +| Every HTTP request/response round-trip | `pytfe.transport` | DEBUG | Zero — guarded by `isEnabledFor(DEBUG)`. The `RoundTrip` object is only constructed when the level is enabled. | +| Retry decisions (`429`, `5xx`, `Retry-After`) | `pytfe.transport` | INFO | One conditional + format-string evaluation. | +| Transport exceptions during retry loop | `pytfe.transport` | DEBUG | Zero (same guard pattern). | + +There is no DEBUG cost when logging is off, even on 10k-request workloads. + +## How to use it in new SDK code + +If you're adding code under `src/pytfe/`, prefer the framework over `print` or ad-hoc `logging.getLogger(__name__)`: + +```python +# resources/something.py +from .._logging import logger + +def some_operation(self, foo): + if logger.isEnabledFor(logging.INFO): + logger.info("performing some_operation on %s", foo) + ... +``` + +Two rules: + +1. **Always guard non-trivial log argument construction** with `isEnabledFor`. Don't pay format/serialize cost when the level is off. +2. **Never log a token, password, or other secret yourself.** Only `RoundTrip` knows how to redact, and it only redacts what it knows about. If you're tempted to write `logger.info("got token %s", token)` — don't. + +For low-level transport additions, use `transport_logger` (also exported from `pytfe._logging`). + +## What this isn't + +- **Not a metrics framework.** No counters, gauges, timing histograms. If you want metrics, wrap the client. +- **Not an audit log.** Logs are for debugging, not for compliance trails. +- **Not a tracing framework.** No correlation IDs, no OpenTelemetry spans. Standard stdlib `logging` only. +- **Not Ansible-aware.** When the Ansible collection imports pytfe, the `pytfe` logger inherits from Ansible's root logger like any other library — which means it stays silent unless the Ansible user explicitly raises the level. No special integration is needed or provided. + +## Checklist when reviewing log-touching code + +- [ ] New library log calls use `pytfe._logging.logger` or `pytfe._logging.transport_logger`, not `logging.getLogger(__name__)` ad hoc +- [ ] Anything more expensive than a literal format string is guarded with `isEnabledFor(...)` +- [ ] No raw tokens, passwords, or other credentials in any log call +- [ ] If logging a header dict, it goes through `redact_headers(...)` +- [ ] If logging a request/response, it uses `RoundTrip(resp).generate()` so the standard redaction + truncation applies +- [ ] Logger default level is unchanged (i.e. NullHandler still active for callers who don't opt in) diff --git a/src/pytfe/__init__.py b/src/pytfe/__init__.py index 9d518c48..82e9b788 100644 --- a/src/pytfe/__init__.py +++ b/src/pytfe/__init__.py @@ -5,6 +5,7 @@ from importlib.metadata import version as _pkg_version from . import errors, models +from ._logging import setup_logging from .client import TFEClient from .config import TFEConfig @@ -13,4 +14,11 @@ except PackageNotFoundError: # running from a source checkout without install __version__ = "0.0.0+unknown" -__all__ = ["TFEConfig", "TFEClient", "errors", "models", "__version__"] +__all__ = [ + "TFEConfig", + "TFEClient", + "errors", + "models", + "setup_logging", + "__version__", +] diff --git a/src/pytfe/_http.py b/src/pytfe/_http.py index ad1e6fd2..c151694f 100644 --- a/src/pytfe/_http.py +++ b/src/pytfe/_http.py @@ -3,6 +3,7 @@ from __future__ import annotations +import logging import re import time from collections.abc import Mapping @@ -12,6 +13,7 @@ import httpx from ._jsonapi import build_headers, parse_error_payload +from ._logging import RoundTrip, transport_logger from .errors import ( AuthError, NotFound, @@ -87,7 +89,6 @@ def request( if headers: hdrs.update(headers) attempt = 0 - # print(method, url, params, json_body, hdrs) while True: try: resp = self._sync.request( @@ -100,6 +101,13 @@ def request( follow_redirects=allow_redirects, ) except httpx.HTTPError as e: + transport_logger.debug( + "transport exception on %s %s (attempt %d): %s", + method, + url, + attempt, + e, + ) if attempt >= self.max_retries: raise ServerError(str(e)) from e self._sleep(attempt, None) @@ -107,6 +115,14 @@ def request( continue if resp.status_code in _RETRY_STATUSES and attempt < self.max_retries: retry_after = _parse_retry_after(resp) + transport_logger.info( + "retrying %s %s after %s (status=%d, attempt=%d)", + method, + url, + f"{retry_after:.2f}s" if retry_after else "backoff", + resp.status_code, + attempt, + ) self._sleep(attempt, retry_after) attempt += 1 continue @@ -114,10 +130,31 @@ def request( # surface 3xx responses to them (so they can read Location) # rather than treating them as errors. if not allow_redirects and 300 <= resp.status_code < 400: + self._log_round_trip(resp) return resp + self._log_round_trip(resp) self._raise_if_error(resp) return resp + def _log_round_trip(self, resp: httpx.Response) -> None: + """Emit a DEBUG-level request/response trace when enabled. + + Cheap when disabled: ``isEnabledFor(DEBUG)`` short-circuits before any + body decoding or JSON parsing happens. + """ + if not transport_logger.isEnabledFor(logging.DEBUG): + return + # Treat binary content types as raw streams so we don't try to JSON + # parse a state-version download or a CV tarball. + ct = (resp.headers.get("content-type") or "").lower() + raw = not ( + "json" in ct + or ct.startswith("text/") + or ct == "" + or "application/vnd.api+json" in ct + ) + transport_logger.debug("\n%s", RoundTrip(resp, raw=raw).generate()) + def _sleep(self, attempt: int, retry_after: float | None) -> None: if retry_after is not None: time.sleep(retry_after) diff --git a/src/pytfe/_logging.py b/src/pytfe/_logging.py new file mode 100644 index 00000000..98297101 --- /dev/null +++ b/src/pytfe/_logging.py @@ -0,0 +1,317 @@ +# Copyright IBM Corp. 2025, 2026 +# SPDX-License-Identifier: MPL-2.0 + +"""Logging primitives for the pytfe SDK. + +Design notes +------------ +The SDK integrates with Python's standard ``logging`` module. By default the +``pytfe`` logger has a ``NullHandler`` attached, so the library is silent +unless the caller opts in — either by configuring ``logging`` themselves +or by calling :func:`setup_logging`, which honours the ``PYTFE_LOG`` +environment variable (``debug`` or ``info``). + +Logger namespace +~~~~~~~~~~~~~~~~ + + * ``pytfe`` — root namespace; rarely emits directly + * ``pytfe.transport`` — HTTP transport request/response/retry trace + +Anything sensitive (the ``Authorization`` bearer token, any header that +looks like a credential, common JSON keys such as ``token`` / ``password`` +/ ``secret``) is replaced with ``**REDACTED**`` before being handed to the +logger. Bodies are truncated to ``PYTFE_LOG_TRUNCATE_BYTES`` (default +``1024``) so DEBUG-level traffic doesn't fill a TTY when listing 10,000 +workspaces. + +""" + +from __future__ import annotations + +import json +import logging +import os +from collections.abc import Mapping +from typing import Any + +import httpx + +__all__ = [ + "logger", + "transport_logger", + "setup_logging", + "RoundTrip", + "redact_headers", + "REDACTED", +] + +REDACTED = "**REDACTED**" + +# Per-namespace loggers. Library code uses these directly; users wire +# handlers/levels onto them. +logger: logging.Logger = logging.getLogger("pytfe") +transport_logger: logging.Logger = logging.getLogger("pytfe.transport") + +# Library best practice: install a NullHandler so the absence of caller +# configuration doesn't trigger "No handlers could be found" warnings or +# bubble logs up to the root logger. +if not any(isinstance(h, logging.NullHandler) for h in logger.handlers): + logger.addHandler(logging.NullHandler()) + + +# Header names that should never appear in plain text. Matched +# case-insensitively against incoming/outgoing headers. +_SENSITIVE_HEADER_NAMES = frozenset( + { + "authorization", + "cookie", + "set-cookie", + "proxy-authorization", + "x-tfc-task-signature", + } +) + +# Header-name substrings that imply sensitivity even when not in the +# explicit list above (third-party run-task webhooks, custom signing +# headers, etc.). +_SENSITIVE_HEADER_SUBSTRINGS = ("token", "secret", "password", "api-key", "apikey") + +# JSON keys whose values are redacted recursively in body dumps. +_SENSITIVE_JSON_KEYS = frozenset( + { + "token", + "access_token", + "refresh_token", + "secret", + "password", + "private_key", + "client_secret", + } +) + + +def _env_int(name: str, default: int) -> int: + raw = os.environ.get(name) + if not raw: + return default + try: + return max(int(raw), 96) + except ValueError: + return default + + +def _env_bool(name: str, default: bool) -> bool: + raw = os.environ.get(name) + if raw is None: + return default + return raw.strip().lower() in {"1", "true", "yes", "on"} + + +def _is_sensitive_header(name: str) -> bool: + n = name.lower() + if n in _SENSITIVE_HEADER_NAMES: + return True + return any(s in n for s in _SENSITIVE_HEADER_SUBSTRINGS) + + +def redact_headers(headers: Mapping[str, str]) -> dict[str, str]: + """Return a copy of ``headers`` with sensitive values replaced.""" + return {k: (REDACTED if _is_sensitive_header(k) else v) for k, v in headers.items()} + + +def setup_logging() -> None: + """Convenience configurator driven by environment variables. + + Honours: + + * ``PYTFE_LOG`` — ``debug`` or ``info`` (case-insensitive). + Anything else is ignored. + * ``PYTFE_LOG_HTTPX`` — if truthy, also raise ``httpx`` to the + same level so low-level connection + activity is visible. + + Calls ``logging.basicConfig`` with a one-line format if no handlers are + already configured on the root logger. Idempotent and safe to call + multiple times. + """ + env = (os.environ.get("PYTFE_LOG") or "").strip().lower() + if env not in {"debug", "info"}: + return + + level = logging.DEBUG if env == "debug" else logging.INFO + + # Only configure handlers if the root logger has none — don't fight + # callers who've already set up their own logging. + if not logging.getLogger().handlers: + logging.basicConfig( + format="[%(asctime)s %(name)s %(levelname)s] %(message)s", + datefmt="%Y-%m-%d %H:%M:%S", + ) + + logger.setLevel(level) + + if _env_bool("PYTFE_LOG_HTTPX", default=False): + logging.getLogger("httpx").setLevel(level) + + +class RoundTrip: + """Format an httpx request/response pair for debug logging. + + Parameters + ---------- + response: + The ``httpx.Response`` returned by the transport. Its ``request`` + attribute supplies the outbound side. + debug_headers: + When ``True``, include request/response headers in the formatted + output. Defaults to the value of ``PYTFE_LOG_HEADERS`` (false). + debug_truncate_bytes: + Per-string truncation budget. Defaults to ``PYTFE_LOG_TRUNCATE_BYTES`` + (``1024``). Values below ``96`` are clamped up. + raw: + When ``True``, mark the bodies as ``[raw stream]`` and skip body + formatting. Use this for binary content (state-version downloads, + configuration-version tarballs, etc.). + """ + + def __init__( + self, + response: httpx.Response, + *, + debug_headers: bool | None = None, + debug_truncate_bytes: int | None = None, + raw: bool = False, + ) -> None: + self._response = response + self._raw = raw + self._debug_headers = ( + debug_headers + if debug_headers is not None + else _env_bool("PYTFE_LOG_HEADERS", default=False) + ) + self._debug_truncate_bytes = max( + debug_truncate_bytes + if debug_truncate_bytes is not None + else _env_int("PYTFE_LOG_TRUNCATE_BYTES", 1024), + 96, + ) + + # ------------------------------------------------------------------ + # Public formatting + # ------------------------------------------------------------------ + + def generate(self) -> str: + request = self._response.request + # httpx.URL has .path / .query (bytes) — render in a way matching + # what the wire saw, but with query unquoted for human reading. + from urllib.parse import unquote, urlparse + + url = urlparse(str(request.url)) + query = f"?{unquote(url.query)}" if url.query else "" + path = unquote(url.path) or "/" + + sb: list[str] = [f"> {request.method} {path}{query}"] + + if self._debug_headers: + for k, v in redact_headers(dict(request.headers)).items(): + sb.append(f"> * {k}: {self._only_n_bytes(v)}") + + if self._raw and request.content: + sb.append("> [raw stream]") + elif request.content: + sb.append(self._redacted_dump("> ", request.content)) + + sb.append( + f"< {self._response.status_code} {self._response.reason_phrase or ''}".rstrip() + ) + + if self._debug_headers: + for k, v in redact_headers(dict(self._response.headers)).items(): + sb.append(f"< * {k}: {self._only_n_bytes(v)}") + + if self._raw: + sb.append("< [raw stream]") + else: + try: + content = self._response.content + except Exception: + content = b"" + if content: + sb.append(self._redacted_dump("< ", content)) + + return "\n".join(sb) + + def __str__(self) -> str: # pragma: no cover - trivial + return self.generate() + + # ------------------------------------------------------------------ + # Helpers + # ------------------------------------------------------------------ + + def _only_n_bytes(self, s: str) -> str: + encoded = s.encode("utf-8", errors="replace") + if len(encoded) <= self._debug_truncate_bytes: + return s + truncated = encoded[: self._debug_truncate_bytes].decode( + "utf-8", errors="replace" + ) + return ( + f"{truncated}... ({len(encoded) - self._debug_truncate_bytes} more bytes)" + ) + + def _redacted_dump(self, prefix: str, body: bytes | str) -> str: + if isinstance(body, bytes): + try: + body = body.decode("utf-8") + except UnicodeDecodeError: + body = repr(body[:64]) + " ...binary..." + if not body: + return "" + try: + parsed = json.loads(body) + except (json.JSONDecodeError, TypeError): + return "\n".join( + f"{prefix}{line}" for line in self._only_n_bytes(body).splitlines() + ) + marshalled = self._recursive_marshal(parsed, self._debug_truncate_bytes) + rendered = json.dumps(marshalled, indent=2, sort_keys=True) + return "\n".join(f"{prefix}{line}" for line in rendered.splitlines()) + + def _recursive_marshal(self, v: Any, budget: int) -> Any: + if isinstance(v, dict): + out: dict[str, Any] = {} + for k in sorted(v.keys()): + if isinstance(k, str) and k.lower() in _SENSITIVE_JSON_KEYS: + out[k] = REDACTED + continue + marshalled = self._recursive_marshal(v[k], budget) + out[k] = marshalled + budget -= len(str(marshalled)) + return out + if isinstance(v, list): + out_list: list[Any] = [] + for i, item in enumerate(v): + if i > 0 and budget <= 0: + out_list.append( + f"... ({len(v) - len(out_list)} additional elements)" + ) + break + marshalled = self._recursive_marshal(item, budget) + out_list.append(marshalled) + budget -= len(str(marshalled)) + return out_list + if isinstance(v, str): + return self._only_n_bytes(v) + return v + + +# Auto-apply environment configuration at import. This is what makes +# ``PYTFE_LOG=debug python my_script.py`` work without the caller adding +# any code. Safe by design: +# +# * No-op unless ``PYTFE_LOG`` is set to ``debug`` or ``info``. +# * Only calls ``logging.basicConfig`` if the root logger has no +# handlers, so existing caller configuration is preserved. +# * Only sets the level on the ``pytfe`` namespace; the root logger +# and other libraries are untouched. +setup_logging() diff --git a/tests/units/test_logging.py b/tests/units/test_logging.py new file mode 100644 index 00000000..b66cd19b --- /dev/null +++ b/tests/units/test_logging.py @@ -0,0 +1,372 @@ +# Copyright IBM Corp. 2025, 2026 +# SPDX-License-Identifier: MPL-2.0 + +"""Unit tests for the pytfe._logging framework.""" + +from __future__ import annotations + +import json +import logging +from unittest.mock import patch + +import httpx +import pytest + +from pytfe._logging import ( + REDACTED, + RoundTrip, + logger, + redact_headers, + setup_logging, + transport_logger, +) + + +def _make_response( + *, + method: str = "GET", + url: str = "https://app.terraform.io/api/v2/organizations/acme/workspaces", + request_headers: dict[str, str] | None = None, + request_content: bytes | None = None, + status: int = 200, + response_headers: dict[str, str] | None = None, + response_content: bytes = b"", +) -> httpx.Response: + req = httpx.Request( + method, url, headers=request_headers or {}, content=request_content + ) + return httpx.Response( + status_code=status, + headers=response_headers or {"content-type": "application/vnd.api+json"}, + content=response_content, + request=req, + ) + + +class TestNamespace: + def test_logger_is_named_pytfe(self): + assert logger.name == "pytfe" + assert transport_logger.name == "pytfe.transport" + # transport_logger inherits from the pytfe root. + assert transport_logger.parent is logger + + def test_null_handler_attached_by_default(self): + """Library must not emit anything until the caller opts in.""" + assert any(isinstance(h, logging.NullHandler) for h in logger.handlers), ( + "the pytfe logger must ship with a NullHandler so library use does " + "not trigger 'No handlers could be found' or bleed into the root logger" + ) + + +class TestRedactHeaders: + @pytest.mark.parametrize( + "header_name", + [ + "Authorization", + "authorization", + "Cookie", + "Set-Cookie", + "Proxy-Authorization", + "X-Tfc-Task-Signature", + "X-Some-Token", + "X-API-Key", + "X-MY-PASSWORD-header", + "x-secret-thing", + ], + ) + def test_redacts_known_sensitive_headers(self, header_name): + out = redact_headers({header_name: "supersecret"}) + assert out[header_name] == REDACTED + + @pytest.mark.parametrize( + "header_name", + ["Content-Type", "Accept", "User-Agent", "X-Request-Id"], + ) + def test_does_not_redact_normal_headers(self, header_name): + out = redact_headers({header_name: "demo"}) + assert out[header_name] == "demo" + + +class TestSetupLogging: + @pytest.fixture(autouse=True) + def _reset_logger(self): + # Each test starts with a clean level for the pytfe logger. + original = logger.level + yield + logger.setLevel(original) + + def test_no_env_no_change(self, monkeypatch): + """Calling setup_logging with no env var must be a no-op.""" + monkeypatch.delenv("PYTFE_LOG", raising=False) + logger.setLevel(logging.WARNING) + setup_logging() + assert logger.level == logging.WARNING + + def test_pytfe_log_debug_sets_debug(self, monkeypatch): + monkeypatch.setenv("PYTFE_LOG", "debug") + setup_logging() + assert logger.level == logging.DEBUG + + def test_pytfe_log_info_sets_info(self, monkeypatch): + monkeypatch.setenv("PYTFE_LOG", "info") + setup_logging() + assert logger.level == logging.INFO + + def test_pytfe_log_garbage_is_ignored(self, monkeypatch): + monkeypatch.setenv("PYTFE_LOG", "verbose-please") + logger.setLevel(logging.WARNING) + setup_logging() + assert logger.level == logging.WARNING + + def test_env_var_alone_activates_logging_at_import(self): + """``PYTFE_LOG=debug python script.py`` must work without the script + calling ``setup_logging()`` explicitly. Verified by spawning a fresh + Python with the env var and looking at stderr. + """ + import subprocess + import sys + + script = ( + "import logging\n" + "from pytfe._logging import logger\n" + # If auto-invoke at import worked, logger.level is DEBUG. + "print('LEVEL', logging.getLevelName(logger.level))\n" + ) + result = subprocess.run( + [sys.executable, "-c", script], + env={"PYTFE_LOG": "debug", "PATH": "/usr/bin:/bin"}, + capture_output=True, + text=True, + check=True, + ) + assert "LEVEL DEBUG" in result.stdout, ( + f"expected logger.level==DEBUG after import with PYTFE_LOG=debug;" + f" stdout={result.stdout!r} stderr={result.stderr!r}" + ) + + def test_pytfe_log_httpx_lifts_httpx_logger(self, monkeypatch): + monkeypatch.setenv("PYTFE_LOG", "info") + monkeypatch.setenv("PYTFE_LOG_HTTPX", "true") + httpx_logger = logging.getLogger("httpx") + original = httpx_logger.level + try: + setup_logging() + assert httpx_logger.level == logging.INFO + finally: + httpx_logger.setLevel(original) + + +class TestRoundTripBasics: + def test_request_and_response_lines(self): + resp = _make_response( + response_content=b'{"data": [{"id": "ws-1", "type": "workspaces"}]}' + ) + out = RoundTrip(resp).generate() + # Request prefix and response prefix. + assert out.startswith("> GET /api/v2/organizations/acme/workspaces") + assert "< 200 OK" in out + + def test_headers_hidden_by_default(self): + resp = _make_response( + request_headers={"Authorization": "Bearer s3cr3t", "Accept": "*/*"}, + response_content=b"{}", + ) + out = RoundTrip(resp).generate() + # No header lines at all unless debug_headers=True. + assert "Accept" not in out + assert "Authorization" not in out + + def test_headers_when_enabled_are_redacted(self): + resp = _make_response( + request_headers={ + "Authorization": "Bearer the-actual-token-please-redact", + "User-Agent": "pytfe/test", + }, + response_content=b"{}", + ) + out = RoundTrip(resp, debug_headers=True).generate() + # Auth value never appears in the log. + assert "the-actual-token-please-redact" not in out + assert REDACTED in out + # Non-sensitive header is fine. httpx lowercases header names. + assert "user-agent: pytfe/test" in out.lower() + + +class TestRoundTripBodyRedaction: + def test_json_body_redacts_sensitive_keys(self): + body = json.dumps( + { + "data": { + "type": "team-tokens", + "attributes": { + "token": "super-secret-token-value", + "description": "harmless", + }, + } + } + ).encode() + resp = _make_response(response_content=body) + out = RoundTrip(resp).generate() + assert "super-secret-token-value" not in out + assert REDACTED in out + assert '"description"' in out # non-sensitive keys still present + + def test_nested_sensitive_key_is_redacted(self): + body = json.dumps( + { + "data": [ + { + "attributes": { + "secret": "nested-secret", + "name": "team-1", + } + } + ] + } + ).encode() + out = RoundTrip(_make_response(response_content=body)).generate() + assert "nested-secret" not in out + assert REDACTED in out + + def test_non_json_body_is_logged_verbatim_after_truncation(self): + resp = _make_response( + response_headers={"content-type": "text/csv"}, + response_content=b"workspace_name,id\nfoo,ws-1\n", + ) + out = RoundTrip(resp).generate() + assert "workspace_name,id" in out + assert "foo,ws-1" in out + + +class TestRoundTripTruncation: + def test_long_string_in_json_is_truncated(self): + big = "x" * 5000 + body = json.dumps({"description": big}).encode() + out = RoundTrip( + _make_response(response_content=body), debug_truncate_bytes=200 + ).generate() + assert "more bytes" in out + # Original full payload must NOT survive. + assert "x" * 5000 not in out + + def test_long_array_is_clipped(self): + items = [{"i": i, "v": "x" * 50} for i in range(500)] + body = json.dumps(items).encode() + out = RoundTrip( + _make_response(response_content=body), debug_truncate_bytes=200 + ).generate() + assert "additional elements" in out + + def test_raw_body_marked_as_stream(self): + # state-version download style — binary content + resp = _make_response( + response_headers={"content-type": "application/octet-stream"}, + response_content=b"\x00\x01\x02" * 1000, + ) + out = RoundTrip(resp, raw=True).generate() + assert "[raw stream]" in out + assert "\x00\x01\x02" not in out + + +class TestTransportIntegration: + """End-to-end: the HTTPTransport must emit one DEBUG round-trip per request + when the pytfe.transport logger is at DEBUG, and zero log records when off.""" + + def _make_transport(self, handler): + from pytfe._http import HTTPTransport + + t = HTTPTransport( + address="https://app.terraform.io", + token="bearer-token-do-not-log", + timeout=5, + verify_tls=True, + user_agent_suffix=None, + max_retries=0, + backoff_base=0, + backoff_cap=0, + backoff_jitter=False, + http2=False, + proxies=None, + ca_bundle=None, + ) + t._sync = httpx.Client(transport=httpx.MockTransport(handler)) + return t + + def test_no_logs_at_default_level(self, caplog): + """With logging at WARNING (default), the transport must say nothing.""" + + def handler(request): + return httpx.Response(200, json={"data": []}) + + t = self._make_transport(handler) + # Ensure default level + with patch.object(transport_logger, "level", logging.NOTSET): + transport_logger.setLevel(logging.WARNING) + with caplog.at_level(logging.WARNING, logger="pytfe.transport"): + t.request("GET", "/api/v2/organizations/acme/workspaces") + assert caplog.records == [] + + def test_debug_emits_round_trip(self, caplog): + """At DEBUG, exactly one round-trip log record per request.""" + + def handler(request): + return httpx.Response( + 200, + json={"data": [{"id": "ws-1", "type": "workspaces"}]}, + headers={"content-type": "application/vnd.api+json"}, + ) + + t = self._make_transport(handler) + original = transport_logger.level + try: + with caplog.at_level(logging.DEBUG, logger="pytfe.transport"): + t.request("GET", "/api/v2/organizations/acme/workspaces") + assert len(caplog.records) == 1 + msg = caplog.records[0].getMessage() + assert "GET /api/v2/organizations/acme/workspaces" in msg + assert "< 200" in msg + assert '"id"' in msg or "ws-1" in msg + # And critically — the bearer token does NOT appear in the formatted + # output because headers are off by default. + assert "bearer-token-do-not-log" not in msg + finally: + transport_logger.setLevel(original) + + def test_retry_logs_at_info(self, caplog): + """5xx that triggers a retry must produce an INFO line.""" + call_count = {"n": 0} + + def handler(request): + call_count["n"] += 1 + if call_count["n"] == 1: + return httpx.Response(503) + return httpx.Response(200, json={"data": []}) + + from pytfe._http import HTTPTransport + + t = HTTPTransport( + address="https://app.terraform.io", + token="x", + timeout=5, + verify_tls=True, + user_agent_suffix=None, + max_retries=2, + backoff_base=0, + backoff_cap=0, + backoff_jitter=False, + http2=False, + proxies=None, + ca_bundle=None, + ) + t._sync = httpx.Client(transport=httpx.MockTransport(handler)) + + original = transport_logger.level + try: + with caplog.at_level(logging.INFO, logger="pytfe.transport"): + t.request("GET", "/api/v2/organizations/acme/workspaces") + info_records = [r for r in caplog.records if r.levelno == logging.INFO] + assert any("retrying" in r.getMessage() for r in info_records), ( + "expected the transport to emit an INFO retry decision on 503" + ) + finally: + transport_logger.setLevel(original)