From 7abf95490027f57d443d72d32a6411bf749ea0cc Mon Sep 17 00:00:00 2001 From: eli Date: Tue, 27 Oct 2026 18:05:30 -0500 Subject: [PATCH 01/17] PER-16680: log through an SDK logger that applies the log settings Ported to main from #137 (Zeev Manilovich), which is stacked on the release-CI draft #136; this carries only #137's own changes. - The client no longer logs its config on creation; it logs the PDP and API URL. - permit.utils.sdk_logger applies log.level and log.label to the SDK's records without touching the application's loguru sinks, and replaces every client's API key with [REDACTED] in what the SDK logs and in PDP error bodies. - PermitConfig.token is repr=False. - ruff bans logging straight to loguru inside the package. - README: what each log option does. Co-Authored-By: Claude Opus 5.5 --- README.md | 32 ++ permit/api/base.py | 8 +- permit/api/context.py | 9 +- permit/config.py | 37 +- permit/enforcement/enforcer.py | 32 +- permit/exceptions.py | 4 +- permit/logger.py | 59 ++- permit/permit.py | 24 +- permit/sync.py | 2 + permit/utils/sdk_logger.py | 114 ++++++ pyproject.toml | 8 + tests/test_fix_logging.py | 695 +++++++++++++++++++++++++++++++++ 12 files changed, 984 insertions(+), 40 deletions(-) create mode 100644 permit/utils/sdk_logger.py create mode 100644 tests/test_fix_logging.py diff --git a/README.md b/README.md index e249ce14..01e3ed49 100644 --- a/README.md +++ b/README.md @@ -40,6 +40,38 @@ calls into the SDK against its type annotations. No pydantic mypy plugin is need - The blocking client, `permit.sync.Permit`, is typed as blocking: `permit.api.users.get("user")` returns a `UserRead`, not a coroutine. +## Logging + +The SDK logs with [loguru](https://github.com/Delgan/loguru) and logs nothing unless you +enable it in the `log` option: + +```py +permit = Permit(token="", log={"enable": True, "level": "debug"}) +``` + +- The SDK adds no loguru sink of its own. Its records go to the sinks your application has + added, or to loguru's default stderr sink, in the format of those sinks. +- `"enable": False` (the default) calls loguru's `logger.disable("permit")`. `"enable": True` + undoes that call, with `logger.enable("permit")`, only if an earlier client made it, so a + `logger.disable()` your application made for `permit` or one of its modules still + applies. When it does undo it, loguru also drops any `permit.*` module disable made since. +- `level` (default `"info"`) is the lowest severity the SDK logs. Its records below it never + reach a sink. Your application's own records are not affected. The SDK logs its HTTP + requests and the PDP's responses at `"debug"`. With `"enable": True`, for a level name + loguru does not know, the SDK logs a warning that names it and uses `"info"`. +- `label` (default `"Permit"`) is put in square brackets before every message the SDK logs. +- `json` is not applied. For JSON output, give your application a serialized sink in place + of loguru's default one: `logger.remove()`, then `logger.add(sys.stderr, serialize=True)`. + Added next to the default sink, it prints every record a second time. +- loguru's logger is process-wide, so these settings are too: the client created last + decides whether the SDK logs, and the last one created with `"enable": True` decides the + level and the label, for every client in the process. `wait_for_sync()` creates no + client: it yields a copy of the client it is called on. +- The SDK replaces the API key of every client in the process with `[REDACTED]` in the + messages it logs and in the PDP error bodies it puts in a `PermitConnectionError`, so a + PDP that echoes the key back does not expose it. A user name and password written into + the `api_url` or `pdp` URL are not replaced: the SDK logs its request URLs at `"debug"`. + ## Deprecations A future major release, permit 4.0, will remove the following. They still work in 3.x, and diff --git a/permit/api/base.py b/permit/api/base.py index def26a01..ea404d50 100644 --- a/permit/api/base.py +++ b/permit/api/base.py @@ -2,10 +2,10 @@ import aiohttp from aiohttp import ClientTimeout -from loguru import logger from permit.api.encoders import jsonable_encoder from permit.utils.pydantic_version import PYDANTIC_VERSION +from permit.utils.sdk_logger import sdk_logger if TYPE_CHECKING: # The v1 API is what runs under either pydantic major, so type-check against it. @@ -68,10 +68,10 @@ def __init__( self._client_config["timeout"] = ClientTimeout(total=timeout) def _log_request(self, url: str, method: str) -> None: - logger.debug(f"Sending HTTP request: {method} {url}") + sdk_logger.debug(f"Sending HTTP request: {method} {url}") def _log_response(self, url: str, method: str, status: int) -> None: - logger.debug(f"Received HTTP response: {method} {url}, status: {status}") + sdk_logger.debug(f"Received HTTP response: {method} {url}, status: {status}") def _prepare_json( self, json: BaseModel | dict[str, Any] | list[Any] | None = None @@ -241,7 +241,7 @@ def _build_http_client( async def _set_context_from_api_key(self) -> None: """Set the API context and permitted access level based on the API key scope.""" - logger.debug("Fetching api key scope") + sdk_logger.debug("Fetching api key scope") scope = await self.__api_keys.get("/scope", model=APIKeyScopeRead) if scope.organization_id is not None: diff --git a/permit/api/context.py b/permit/api/context.py index 9d72d835..72d3b5df 100644 --- a/permit/api/context.py +++ b/permit/api/context.py @@ -1,8 +1,7 @@ from enum import Enum -from loguru import logger - from permit.exceptions import PermitContextChangeError +from permit.utils.sdk_logger import sdk_logger class ApiKeyAccessLevel(str, Enum): @@ -198,7 +197,7 @@ def set_organization_level_context(self, org: str) -> None: org: The organization key. """ self.__verify_can_access_org(org) - logger.debug(f"Setting organization level context: {org}") + sdk_logger.debug(f"Setting organization level context: {org}") self._context_level = ApiContextLevel.ORGANIZATION self._organization = org self._project = None @@ -212,7 +211,7 @@ def set_project_level_context(self, org: str, project: str) -> None: project: The project key. """ self.__verify_can_access_project(org, project) - logger.debug(f"Setting project level context: {org}/{project}") + sdk_logger.debug(f"Setting project level context: {org}/{project}") self._context_level = ApiContextLevel.PROJECT self._organization = org self._project = project @@ -227,7 +226,7 @@ def set_environment_level_context(self, org: str, project: str, environment: str environment: The environment key. """ self.__verify_can_access_environment(org, project, environment) - logger.debug(f"Setting environment level context: {org}/{project}/{environment}") + sdk_logger.debug(f"Setting environment level context: {org}/{project}/{environment}") self._context_level = ApiContextLevel.ENVIRONMENT self._organization = org self._project = project diff --git a/permit/config.py b/permit/config.py index 7a42f941..490c6576 100644 --- a/permit/config.py +++ b/permit/config.py @@ -13,22 +13,46 @@ class LoggerConfig(BaseModel): - """Logging settings of the SDK.""" + """Logging settings of the SDK. + + The SDK logs with loguru and adds no sink of its own: its records go to the loguru sinks + the application has added, or to loguru's default stderr sink, in the format of those + sinks. loguru's logger is process-wide, so these settings are too: the client created + last decides whether the SDK logs, and the last one created with `enable` True decides + the level and the label, for every client in the process. + + Whatever these settings, the SDK replaces the API key of every client in the process + with `[REDACTED]` in the messages it logs and in the PDP error bodies it puts in a + `PermitConnectionError`. A user name and password written into the `api_url` or `pdp` + URL are not replaced. + """ enable: bool = Field( - default=False, description="Whether or not to enable logging from the Permit library" + default=False, + description="Whether the SDK logs. False calls loguru's logger.disable('permit'), so " + "nothing is logged. True undoes that call with logger.enable('permit') if an earlier " + "client made it, and otherwise leaves loguru's switches alone, so a logger.disable() " + "the application made for 'permit' or one of its modules still applies.", ) level: str = Field( - default="info", description="Sets the log level configured for the Permit SDK Logger." + default="info", + description="The lowest severity the SDK logs, such as 'debug', 'info', 'warning' or " + "'error', in any case; 'warn' and 'fatal' are read as 'warning' and 'critical'. The SDK " + "drops its records below it before they reach any sink. " + "Read only when enable is True; for a name loguru does not know, the SDK logs a " + "warning and uses 'info'.", ) label: str = Field( default="Permit", - description="Sets the label configured for logs emitted by the Permit SDK Logger.", + description="Put in square brackets before the message of every record the SDK logs, " + "as in '[Permit] ...'. An empty string adds nothing. Read only when enable is True.", ) log_as_json: bool = Field( default=False, alias="json", - description="Sets whether the SDK log output should be in JSON format.", + description="Not applied. The format of the SDK's records is that of the loguru sinks " + "they reach. For JSON, the application replaces loguru's default sink with a " + "serialized one: logger.remove(), then logger.add(sys.stderr, serialize=True).", ) @@ -54,8 +78,11 @@ class PermitConfig(BaseModel): # A positional `...`, not `default=...`: type checkers take any `default=` # keyword as a default, so `PermitConfig()` without a token would pass them. + # repr=False keeps the key out of repr() and str() of the config, and so out of + # tracebacks that print frame values, such as loguru's with diagnose=True. token: str = Field( ..., + repr=False, description="The token (API Key) used for authorization against the PDP " "and the Permit REST API.", ) diff --git a/permit/enforcement/enforcer.py b/permit/enforcement/enforcer.py index 119a5d4e..c9d51027 100644 --- a/permit/enforcement/enforcer.py +++ b/permit/enforcement/enforcer.py @@ -5,7 +5,6 @@ import aiohttp from aiohttp import ClientTimeout -from loguru import logger from typing_extensions import NotRequired, TypedDict from permit.config import PermitConfig @@ -14,6 +13,7 @@ from permit.utils.context import Context, ContextStore from permit.utils.dicts import deep_merge from permit.utils.pydantic_version import PYDANTIC_VERSION +from permit.utils.sdk_logger import sdk_logger from permit.utils.sync import SyncClass if TYPE_CHECKING: @@ -53,7 +53,15 @@ async def read_error_body(response: aiohttp.ClientResponse) -> str: surrounding handler and re-reported as "cannot connect to the PDP container". A 403 for a wrong API key was indistinguishable from the PDP being down, which is a genuinely misleading error to hand a user. + + Every API key the SDK knows is replaced with ``[REDACTED]``: the body goes into + the SDK's log record and into the PermitConnectionError raised to the caller, + and a PDP may echo back the key it rejected. """ + return sdk_logger.scrub(await _read_body_text(response)) + + +async def _read_body_text(response: aiohttp.ClientResponse) -> str: try: return repr(await response.json()) except (aiohttp.ClientError, ValueError): @@ -179,7 +187,7 @@ async def authorized_users( raise PermitConnectionError(msg) error_body = await read_error_body(response) - logger.error( + sdk_logger.error( "error in permit.authorized_users({}, {}):\n{}\n{}".format( action, self._resource_repr(normalized_resource), @@ -198,7 +206,7 @@ async def authorized_users( raise PermitConnectionError(msg) content: dict[str, Any] = await response.json() - logger.debug( + sdk_logger.debug( f"permit.authorized_users() response:" f"\ninput: {pformat(request_body, indent=2)}" f"\nresponse status: {response.status}" @@ -207,7 +215,7 @@ async def authorized_users( result: AuthorizedUsersResult = parse_obj_as(AuthorizedUsersResult, content) return result except aiohttp.ClientError as err: - logger.error( + sdk_logger.error( f"error in permit.authorized_users({action}, " f"{self._resource_repr(normalized_resource)}):\n{err}" ) @@ -314,10 +322,10 @@ async def bulk_check( f"status code: {response.status}", error_body, ) - logger.error(msg) + sdk_logger.error(msg) raise PermitConnectionError(msg) content: dict[str, Any] = await response.json() - logger.debug( + sdk_logger.debug( f"permit.check() response:\n" f"input: {pformat(request_body, indent=2)}\n" f"response status: {response.status}\n" @@ -339,7 +347,7 @@ async def bulk_check( ), err, ) - logger.error(msg) + sdk_logger.error(msg) raise PermitConnectionError(msg, error=err) from err return decisions @@ -416,7 +424,7 @@ async def check( raise PermitConnectionError(msg) error_body = await read_error_body(response) - logger.error( + sdk_logger.error( "error in permit.check({}, {}, {}):\n{}\n{}".format( normalized_user, action, @@ -436,7 +444,7 @@ async def check( raise PermitConnectionError(msg) content: dict[str, Any] = await response.json() - logger.debug( + sdk_logger.debug( f"permit.check() response:\n" f"body: {pformat(body, indent=2)}\n" f"response status: {response.status}\n" @@ -445,7 +453,7 @@ async def check( decision: bool = bool(content.get("allow", False)) return decision except aiohttp.ClientError as err: - logger.error( + sdk_logger.error( f"error in permit.check({normalized_user}, {action}, " f"{self._resource_repr(normalized_resource)}):" f"\n{err}" @@ -514,7 +522,7 @@ async def get_user_permissions( else content ) - logger.debug( + sdk_logger.debug( f"permit.get_user_permissions() response:\n" f"input: {pformat(input_data, indent=2)}\n" f"response data: {pformat(permissions, indent=2)}" @@ -522,7 +530,7 @@ async def get_user_permissions( return permissions except aiohttp.ClientError as err: - logger.error(f"Error in permit.get_user_permissions(): {err}") + sdk_logger.error(f"Error in permit.get_user_permissions(): {err}") msg = ( f"Permit SDK got error: {err}, \n" f"and cannot connect to the PDP container, please check your configuration " diff --git a/permit/exceptions.py b/permit/exceptions.py index 5a71176e..319b1dac 100644 --- a/permit/exceptions.py +++ b/permit/exceptions.py @@ -5,10 +5,10 @@ from typing import TYPE_CHECKING, Any, TypeVar import aiohttp -from loguru import logger from typing_extensions import ParamSpec, deprecated from permit.utils.pydantic_version import PYDANTIC_VERSION +from permit.utils.sdk_logger import sdk_logger if TYPE_CHECKING: # The v1 API is what runs under either pydantic major, so type-check against it. @@ -288,7 +288,7 @@ async def wrapped(*args: P.args, **kwargs: P.kwargs) -> R: try: return await func(*args, **kwargs) except aiohttp.ClientError as err: - logger.error(f"got client error while sending an http request:\n{err}") + sdk_logger.error(f"got client error while sending an http request:\n{err}") msg = f"{err}" raise PermitConnectionError(msg, error=err) from err diff --git a/permit/logger.py b/permit/logger.py index d1677f87..48f35113 100644 --- a/permit/logger.py +++ b/permit/logger.py @@ -1,15 +1,66 @@ +import contextlib + from loguru import logger from permit.config import PermitConfig +from permit.utils.sdk_logger import PACKAGE, sdk_logger + +PERMIT_MODULE = PACKAGE -PERMIT_MODULE = "permit" +# The names Python's logging module also accepts, and the ones the Node SDK's logger uses. +_LEVEL_ALIASES = {"WARN": "WARNING", "FATAL": "CRITICAL"} def configure_logger(config: PermitConfig) -> None: - """Silence the SDK's loguru output unless the config enables logging. + """Apply the `log` settings of `config` to the SDK's log records. + + The settings are process-wide, as loguru's logger is: the client created last decides + whether the SDK logs, and the last one created with `log.enable` True decides the level + and the label, for every client. The SDK adds no sink and leaves the application's sinks + and levels alone, so its records are written wherever loguru writes the application's, + in the format of those sinks. + + - `log.enable` False calls `logger.disable("permit")`, so nothing is logged. True + undoes that call with `logger.enable("permit")` if an earlier client made it, and + otherwise leaves loguru's switches alone, so a `logger.disable` the application made + for the package or one of its modules still applies. + - `log.level` drops the SDK's records below that severity before they reach any sink. + - `log.label` is put in brackets before each message. + - `log.log_as_json` is not applied: loguru serializes per sink. For JSON output, the + application replaces loguru's default sink with a serialized one: `logger.remove()`, + then `logger.add(sys.stderr, serialize=True)`. + + Whatever the settings, the API key in `config.token` is replaced with `[REDACTED]` in + every message the SDK logs and in the PDP error bodies it puts in a + `PermitConnectionError`. + + An unknown `log.level` does not fail client creation: the SDK logs a warning that names + the value and uses INFO. Args: - config: The SDK configuration; only `config.log.enable` is read. + config: The SDK configuration. """ + sdk_logger.redact(config.token) if not config.log.enable: - logger.disable(PERMIT_MODULE) + sdk_logger.disable() + return + level_no = _level_no(config.log.level) + if level_no is None: + sdk_logger.enable(min_level_no=logger.level("INFO").no, label=config.log.label) + sdk_logger.warning( + f"Unknown log level {config.log.level!r} in the Permit SDK config (log.level), " + "so the SDK logs at INFO. Use trace, debug, info, success, warning, error or " + "critical, or a level added with loguru's logger.level()." + ) + return + sdk_logger.enable(min_level_no=level_no, label=config.log.label) + + +def _level_no(level: str) -> int | None: + upper = level.upper() + # loguru's level names are case-sensitive: try the name as given first, so a level the + # application added in lower case is found, then the upper-case name of a built-in one. + for name in (level, _LEVEL_ALIASES.get(upper, upper)): + with contextlib.suppress(ValueError): + return logger.level(name).no + return None diff --git a/permit/permit.py b/permit/permit.py index 51d6f51f..a636a05c 100644 --- a/permit/permit.py +++ b/permit/permit.py @@ -1,9 +1,8 @@ -import json +import copy from collections.abc import Generator from contextlib import contextmanager from typing import Any, Literal -from loguru import logger from typing_extensions import Self from permit.api.api_client import PermitApiClient @@ -20,6 +19,7 @@ from permit.logger import configure_logger from permit.pdp_api.pdp_api_client import PermitPdpApiClient from permit.utils.context import Context +from permit.utils.sdk_logger import sdk_logger class Permit: @@ -35,14 +35,17 @@ def __init__(self, config: PermitConfig | None = None, **options: Any) -> None: self._config: PermitConfig = config if config is not None else PermitConfig(**options) configure_logger(self._config) + self._connect() + sdk_logger.debug( + f"Permit SDK initialized: api_url={self._config.api_url}, pdp={self._config.pdp}" + ) + + def _connect(self) -> None: + """Create the clients that send this client's requests, from its config.""" self._enforcer = Enforcer(self._config) self._api = PermitApiClient(self._config) self._elements = ElementsApi(self._config) self._pdp_api = PermitPdpApiClient(self._config) - logger.debug( - "Permit SDK initialized with config:\n${}", - json.dumps(self._config.dict(exclude={"api_context"})), - ) @property def config(self) -> PermitConfig: @@ -81,7 +84,7 @@ def wait_for_sync( https://docs.permit.io/how-to/manage-data/local-facts-uploader """ if not self._config.proxy_facts_via_pdp: - logger.warning( + sdk_logger.warning( "Tried to wait for synced facts but proxy_facts_via_pdp is disabled, ignoring..." ) yield self @@ -90,7 +93,12 @@ def wait_for_sync( contextualized_config.facts_sync_timeout = timeout if policy is not None: contextualized_config.facts_sync_timeout_policy = policy - yield self.__class__(contextualized_config) + # A copy of this client that sends its requests with the new config. Creating a new + # client instead would apply its log settings to the whole process again. + waiting: Self = copy.copy(self) + waiting._config = contextualized_config + waiting._connect() + yield waiting @property def api(self) -> PermitApiClient: diff --git a/permit/sync.py b/permit/sync.py index c2e066ad..84bc0d7b 100644 --- a/permit/sync.py +++ b/permit/sync.py @@ -31,6 +31,8 @@ class Permit(AsyncPermit): def __init__(self, config: PermitConfig | None = None, **options: Any) -> None: super().__init__(config, **options) + + def _connect(self) -> None: self._enforcer = SyncEnforcer(self._config) # type: ignore[assignment] self._api = SyncPermitApiClient(self._config) # type: ignore[assignment] self._elements = SyncElementsApi(self._config) # type: ignore[assignment] diff --git a/permit/utils/sdk_logger.py b/permit/utils/sdk_logger.py new file mode 100644 index 00000000..07faed11 --- /dev/null +++ b/permit/utils/sdk_logger.py @@ -0,0 +1,114 @@ +import threading + +from loguru import logger + +REDACTED = "[REDACTED]" +# The package whose records loguru's logger.enable() and logger.disable() switch on and off. +PACKAGE = "permit" + + +class SdkLogger: + """Logs the SDK's own records to loguru's logger, applying the SDK's `log` settings. + + Each record reaches loguru from the SDK module that logged it, so + `logger.disable("permit")`, `logger.enable("permit")` and the application's sinks treat + it as a record of that module. On the way, this drops records below the minimum + severity, replaces every registered API key with `[REDACTED]` and prefixes the message + with the label. + + Its settings are process-wide, like loguru's logger. Until `enable` is called, it + keeps every record and adds no label. + """ + + def __init__(self) -> None: + self._min_level_no = 0 + self._label = "" + # Whether `disable` called logger.disable("permit") after the last `enable`. + self._disabled_package = False + self._secrets_lock = threading.Lock() + # Longest first: where one secret contains another, such as a key and a prefix of + # it, the whole of the longer one is replaced, not just the shorter part. Replaced, + # never mutated, so a thread that logs while another registers a secret reads + # either the old tuple or the new one. + self._secrets: tuple[str, ...] = () + + def disable(self) -> None: + """Stop loguru from passing on any record of the package: `logger.disable("permit")`.""" + logger.disable(PACKAGE) + self._disabled_package = True + + def enable(self, *, min_level_no: int, label: str) -> None: + """Keep the records from `min_level_no` up, with `label` before each message. + + If `disable` was called since the last `enable`, this undoes it with + `logger.enable("permit")`. Otherwise it leaves loguru's switches alone: loguru's + enable would also drop every `logger.disable` the application set for a module of + the package, and override an application-wide `logger.disable("")`. + + Args: + min_level_no: The loguru severity number below which records are dropped. + label: The text put in brackets before each message; an empty string adds none. + """ + self._min_level_no = min_level_no + self._label = label + if self._disabled_package: + logger.enable(PACKAGE) + self._disabled_package = False + + def redact(self, secret: str) -> None: + """Replace `secret` with `[REDACTED]` in every record logged from now on. + + The secret without its leading and trailing whitespace is replaced too: a key read + from a file or an environment variable may end with a space, which an HTTP server + that echoes the key back has stripped. + + Args: + secret: A credential, such as an API key. A secret that is empty or only + whitespace is ignored. + """ + trimmed = secret.strip() + if not trimmed: + return + with self._secrets_lock: + new = {secret, trimmed}.difference(self._secrets) + if new: + self._secrets = tuple(sorted((*self._secrets, *new), key=len, reverse=True)) + + def scrub(self, text: str) -> str: + """Return `text` with every registered secret replaced with `[REDACTED]`. + + Args: + text: Any text the SDK logs or puts in an exception. + + Returns: + The text without any registered secret. + """ + for secret in self._secrets: + text = text.replace(secret, REDACTED) + return text + + def debug(self, message: str) -> None: + """Log `message` with severity DEBUG.""" + self._log("DEBUG", message) + + def warning(self, message: str) -> None: + """Log `message` with severity WARNING.""" + self._log("WARNING", message) + + def error(self, message: str) -> None: + """Log `message` with severity ERROR.""" + self._log("ERROR", message) + + def _log(self, level: str, message: str) -> None: + if logger.level(level).no < self._min_level_no: + return + message = self.scrub(message) + if self._label: + message = f"[{self._label}] {message}" + # depth=2 skips this method and the one that called it, so loguru attributes the + # record to the SDK module that logged it. The message goes without arguments, so + # loguru does not call str.format on it and braces in it are kept as they are. + logger.opt(depth=2).log(level, message) + + +sdk_logger = SdkLogger() diff --git a/pyproject.toml b/pyproject.toml index d177b569..3ef409a0 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -242,6 +242,11 @@ convention = "google" [tool.ruff.lint.flake8-tidy-imports] ban-relative-imports = "all" +[tool.ruff.lint.flake8-tidy-imports.banned-api] +# A record logged straight to loguru would skip the SDK's log level and label, and the +# replacement of the API key with [REDACTED] (PER-16680). +"loguru.logger".msg = "Log through permit.utils.sdk_logger, which redacts the API key." + [tool.ruff.lint.flake8-type-checking] # pydantic evaluates field annotations at runtime, so the imports they use # must never be moved under `if TYPE_CHECKING:`. @@ -271,7 +276,10 @@ runtime-evaluated-base-classes = ["pydantic.BaseModel", "pydantic.v1.BaseModel"] "T201", # progress output for long e2e runs; pytest captures it "BLE001", # e2e tests turn any unexpected exception into a readable pytest.fail "S603", # subprocesses run the interpreter under test with the test's own arguments + "TID251", # tests add loguru sinks and log the way an application does ] +# The SDK's loguru wrapper, and the module that reads loguru's levels for log.level. +"permit/{logger,utils/sdk_logger}.py" = ["TID251"] # These are standalone CLI programs, not library code: writing the rendered # report to stdout IS their interface, so the "no print" rule does not apply. "{.github/scripts,scripts,skills/permit-python-3-migration/scripts}/*.py" = [ diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py new file mode 100644 index 00000000..5422f424 --- /dev/null +++ b/tests/test_fix_logging.py @@ -0,0 +1,695 @@ +"""Offline tests for the SDK's logging (PER-16680). + +The SDK logs through loguru's process-wide logger and adds no sink of its own. These tests +add sinks the way an application does, and read what reached them: a text sink on stderr in +loguru's default format, read through capsys, and a serialized (JSON) sink. Every request is +served by a local pytest_httpserver. +""" + +import json +import re +import subprocess +import sys +import types +from collections.abc import Iterator +from dataclasses import dataclass, field +from pathlib import Path +from typing import Any + +import pytest +from loguru import logger +from pytest_httpserver import HTTPServer +from werkzeug import Request, Response + +from permit import Permit, PermitConfig +from permit.enforcement.enforcer import CheckQuery +from permit.exceptions import PermitConnectionError +from permit.sync import Permit as SyncPermit +from permit.utils.sdk_logger import REDACTED, SdkLogger, sdk_logger + +SENTINEL = "permit_key_SENTINEL_9f8e7d6c5b4a39281706f5e4d3c2b1a0" +ORG_ID = "00000000-0000-4000-8000-00000000000a" +PROJECT_ID = "00000000-0000-4000-8000-00000000000b" +ENV_ID = "00000000-0000-4000-8000-00000000000c" +USERS = f"/v2/facts/{PROJECT_ID}/{ENV_ID}/users" +WAIT_FOR_SYNC_WARNING = "Tried to wait for synced facts" + + +def _probe() -> None: + logger.log("TRACE", "permit logging probe") + + +def _permit_records_enabled() -> bool: + """Whether loguru lets the records of the permit package through right now. + + loguru has no getter for this, so log a TRACE record from a function whose module name + is in the package, and see whether a sink receives it. + """ + received: list[str] = [] + probe_module = "permit._logging_probe" + sink_id = logger.add( + received.append, level="TRACE", filter=lambda record: record["name"] == probe_module + ) + try: + types.FunctionType(_probe.__code__, {"__name__": probe_module, "logger": logger})() + finally: + logger.remove(sink_id) + return bool(received) + + +@pytest.fixture(autouse=True) +def isolated_logging() -> Iterator[None]: + """Start as a fresh process does, and put the SdkLogger and loguru's switches back after. + + Restoring loguru's switch for "permit" also drops any switch a test set for a module of + the package. + """ + was_enabled = _permit_records_enabled() + saved = vars(sdk_logger).copy() + vars(sdk_logger).update(vars(SdkLogger())) + logger.enable("permit") + yield + vars(sdk_logger).update(saved) + if was_enabled: + logger.enable("permit") + else: + logger.disable("permit") + + +@dataclass +class AppSinks: + """What the application's own loguru sinks received during a test.""" + + capsys: pytest.CaptureFixture[str] + json_lines: list[str] = field(default_factory=list) + _stderr: str = "" + + def stderr(self) -> str: + captured = self.capsys.readouterr() + assert captured.out == "" + self._stderr += captured.err + return self._stderr + + def everything(self) -> str: + return self.stderr() + "".join(self.json_lines) + + def records(self) -> list[dict[str, Any]]: + return [json.loads(line)["record"] for line in self.json_lines] + + def sdk_records(self) -> list[dict[str, Any]]: + return [ + record + for record in self.records() + if record["name"] == "permit" or record["name"].startswith("permit.") + ] + + def sdk_levels(self) -> set[str]: + return {record["level"]["name"] for record in self.sdk_records()} + + def wait_for_sync_warnings(self) -> list[dict[str, Any]]: + """The records of the warning `wait_for_sync` logs when facts are not proxied.""" + return [ + record for record in self.sdk_records() if WAIT_FOR_SYNC_WARNING in record["message"] + ] + + +def write_to_stderr(message: str) -> None: + """Write to the sys.stderr of the moment: capsys replaces it in each phase of a test.""" + sys.stderr.write(message) + + +@pytest.fixture +def app_sinks(capsys: pytest.CaptureFixture[str]) -> Iterator[AppSinks]: + """A stderr sink in loguru's default format and a JSON sink, both at DEBUG.""" + sinks = AppSinks(capsys) + sink_ids = [ + logger.add(write_to_stderr, level="DEBUG"), + logger.add(sinks.json_lines.append, level="DEBUG", serialize=True), + ] + yield sinks + for sink_id in sink_ids: + logger.remove(sink_id) + + +def make_config(httpserver: HTTPServer, *, token: str = SENTINEL, **log: Any) -> PermitConfig: + url = httpserver.url_for("").rstrip("/") + return PermitConfig(token=token, api_url=url, pdp=url, log=log) + + +def serve(httpserver: HTTPServer) -> None: + """Answer the requests `use_async_client` and `use_sync_client` make.""" + httpserver.expect_request("/v2/api-key/scope", method="GET").respond_with_json( + {"organization_id": ORG_ID, "project_id": PROJECT_ID, "environment_id": ENV_ID} + ) + httpserver.expect_request(USERS, method="GET").respond_with_json( + {"data": [], "total_count": 0, "page_count": 0} + ) + # Not JSON, so reading the response raises an aiohttp error, which the SDK logs. + httpserver.expect_request(f"{USERS}/user-1", method="GET").respond_with_data( + "not json", content_type="text/plain" + ) + httpserver.expect_request("/allowed", method="POST").respond_with_json({"allow": True}) + httpserver.expect_request("/allowed/bulk", method="POST").respond_with_data( + "PDP failure", status=500 + ) + + +BULK: list[CheckQuery] = [{"user": "user-1", "action": "read", "resource": "document"}] + + +async def use_async_client(permit: Permit) -> None: + """Go through every kind of record the SDK logs: DEBUG, WARNING and ERROR.""" + with permit.wait_for_sync(): + pass + assert await permit.check("user-1", "read", "document") + await permit.api.users.list() + with pytest.raises(PermitConnectionError): + await permit.api.users.get("user-1") + with pytest.raises(PermitConnectionError): + await permit.bulk_check(BULK) + + +def use_sync_client(permit: SyncPermit) -> None: + """The blocking twin of `use_async_client`.""" + with permit.wait_for_sync(): + pass + assert permit.check("user-1", "read", "document") + permit.api.users.list() + with pytest.raises(PermitConnectionError): + permit.api.users.get("user-1") + with pytest.raises(PermitConnectionError): + permit.bulk_check(BULK) + + +def assert_api_key_not_logged( + httpserver: HTTPServer, app_sinks: AppSinks, expected_levels: set[str] +) -> None: + # The key was in use: every request carried it. + sent = {request.headers.get("Authorization") for request, _ in httpserver.log} + assert sent == {f"Bearer {SENTINEL}"} + output = app_sinks.everything() + assert SENTINEL not in output + # Nothing was redacted either: no SDK record held the key in the first place. + assert REDACTED not in output + assert app_sinks.sdk_levels() == expected_levels + # Each SDK record is one line on stderr, in the sink's format. + assert app_sinks.stderr().count(" | permit.") == len(app_sinks.sdk_records()) + + +LOG_LEVELS = [ + pytest.param({"level": "debug"}, {"DEBUG", "WARNING", "ERROR"}, id="debug"), + pytest.param({"level": "info"}, {"WARNING", "ERROR"}, id="info"), + pytest.param({}, {"WARNING", "ERROR"}, id="unset"), +] +AS_JSON = [pytest.param(True, id="json"), pytest.param(False, id="text")] + + +@pytest.mark.parametrize(("log", "expected_levels"), LOG_LEVELS) +@pytest.mark.parametrize("as_json", AS_JSON) +async def test_async_client_never_logs_the_api_key( + httpserver: HTTPServer, + app_sinks: AppSinks, + log: dict[str, str], + expected_levels: set[str], + *, + as_json: bool, +) -> None: + serve(httpserver) + + await use_async_client(Permit(make_config(httpserver, enable=True, json=as_json, **log))) + + assert_api_key_not_logged(httpserver, app_sinks, expected_levels) + + +@pytest.mark.parametrize(("log", "expected_levels"), LOG_LEVELS) +@pytest.mark.parametrize("as_json", AS_JSON) +def test_sync_client_never_logs_the_api_key( + httpserver: HTTPServer, + app_sinks: AppSinks, + log: dict[str, str], + expected_levels: set[str], + *, + as_json: bool, +) -> None: + serve(httpserver) + + use_sync_client(SyncPermit(make_config(httpserver, enable=True, json=as_json, **log))) + + assert_api_key_not_logged(httpserver, app_sinks, expected_levels) + + +def echo_the_key(request: Request) -> Response: + """A PDP that rejects the request and echoes the API key it was sent.""" + return Response(f"rejected key: {request.headers['Authorization']}", status=403) + + +@pytest.mark.parametrize("enabled_by", ["config", "application"]) +async def test_an_api_key_the_pdp_echoes_back_is_redacted( + httpserver: HTTPServer, app_sinks: AppSinks, enabled_by: str +) -> None: + httpserver.expect_request("/allowed", method="POST").respond_with_handler(echo_the_key) + if enabled_by == "config": + permit = Permit(make_config(httpserver, enable=True)) + else: + # A client created with logging disabled, whose records the application turns on. + permit = Permit(make_config(httpserver)) + logger.enable("permit") + + with pytest.raises(PermitConnectionError) as raised: + await permit.check("user-1", "read", "document") + + [record] = [record for record in app_sinks.sdk_records() if record["level"]["name"] == "ERROR"] + assert f"rejected key: Bearer {REDACTED}" in record["message"] + assert SENTINEL not in app_sinks.everything() + # The application gets the body too, in the exception it may log or report. + assert f"rejected key: Bearer {REDACTED}" in str(raised.value) + assert SENTINEL not in str(raised.value) + + +async def test_errors_raised_for_a_pdp_that_echoes_the_key_do_not_hold_it( + httpserver: HTTPServer, +) -> None: + for path in ("/allowed", "/allowed/bulk", "/authorized_users"): + httpserver.expect_request(path, method="POST").respond_with_handler(echo_the_key) + permit = Permit(make_config(httpserver)) + sync_permit = SyncPermit(make_config(httpserver)) + + raised: list[PermitConnectionError] = [] + for call in ( + lambda: permit.check("user-1", "read", "document"), + lambda: permit.bulk_check(BULK), + lambda: permit.authorized_users("read", "document"), + ): + with pytest.raises(PermitConnectionError) as error: + await call() + raised.append(error.value) + with pytest.raises(PermitConnectionError) as error: + sync_permit.check("user-1", "read", "document") + raised.append(error.value) + + for error_value in raised: + assert f"rejected key: Bearer {REDACTED}" in str(error_value) + assert SENTINEL not in str(error_value) + + +async def test_a_key_is_redacted_whole_when_another_key_is_a_prefix_of_it( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + # Clients created earlier in the process with keys the real key starts with. + for length in range(len("permit_key_"), len(SENTINEL), 2): + Permit(make_config(httpserver, token=SENTINEL[:length], enable=True)) + httpserver.expect_request("/allowed", method="POST").respond_with_handler(echo_the_key) + permit = Permit(make_config(httpserver, enable=True)) + + with pytest.raises(PermitConnectionError): + await permit.check("user-1", "read", "document") + + [record] = [record for record in app_sinks.sdk_records() if record["level"]["name"] == "ERROR"] + assert record["message"].endswith(f"rejected key: Bearer {REDACTED}") + assert SENTINEL[-8:] not in app_sinks.everything() + + +async def test_a_key_with_a_trailing_space_is_redacted_when_echoed_without_it( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + httpserver.expect_request("/allowed", method="POST").respond_with_handler(echo_the_key) + permit = Permit(make_config(httpserver, token=f"{SENTINEL} ", enable=True)) + + with pytest.raises(PermitConnectionError): + await permit.check("user-1", "read", "document") + + [record] = [record for record in app_sinks.sdk_records() if record["level"]["name"] == "ERROR"] + assert record["message"].endswith(f"rejected key: Bearer {REDACTED}") + assert SENTINEL not in app_sinks.everything() + + +@pytest.mark.parametrize( + ("log", "expected_levels"), + [ + pytest.param({"level": "trace"}, {"DEBUG", "WARNING", "ERROR"}, id="trace"), + pytest.param({"level": "debug"}, {"DEBUG", "WARNING", "ERROR"}, id="debug"), + pytest.param({}, {"WARNING", "ERROR"}, id="unset"), + pytest.param({"level": "INFO"}, {"WARNING", "ERROR"}, id="INFO"), + pytest.param({"level": "warning"}, {"WARNING", "ERROR"}, id="warning"), + pytest.param({"level": "warn"}, {"WARNING", "ERROR"}, id="warn"), + pytest.param({"level": "error"}, {"ERROR"}, id="error"), + pytest.param({"level": "critical"}, set(), id="critical"), + ], +) +async def test_level_drops_the_sdk_records_below_it( + httpserver: HTTPServer, app_sinks: AppSinks, log: dict[str, str], expected_levels: set[str] +) -> None: + serve(httpserver) + + await use_async_client(Permit(make_config(httpserver, enable=True, **log))) + logger.debug("an application record") + + assert app_sinks.sdk_levels() == expected_levels + # The application's own records are not the SDK's to filter. + assert "an application record" in [record["message"] for record in app_sinks.records()] + + +async def test_an_unknown_level_warns_and_logs_at_info( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + serve(httpserver) + + await use_async_client(Permit(make_config(httpserver, enable=True, level="verbose"))) + + warnings = [ + record + for record in app_sinks.sdk_records() + if record["level"]["name"] == "WARNING" + and "Unknown log level 'verbose'" in record["message"] + ] + assert len(warnings) == 1 + assert "logs at INFO" in warnings[0]["message"] + # The same records as with level "info": no DEBUG ones. + assert app_sinks.sdk_levels() == {"WARNING", "ERROR"} + + +def test_the_traceback_of_a_failed_client_creation_hides_the_api_key( + httpserver: HTTPServer, monkeypatch: pytest.MonkeyPatch +) -> None: + def fail(**_: object) -> None: + msg = "the SDK could not configure its logger" + raise RuntimeError(msg) + + monkeypatch.setattr("permit.logger.sdk_logger.enable", fail) + lines: list[str] = [] + # diagnose=True, loguru's default, prints the value of each name on every line of the + # traceback, and the SDK's frames pass the config around. + sink_id = logger.add(lines.append, diagnose=True, backtrace=True) + config = make_config(httpserver, enable=True) + try: + try: + SyncPermit(config) + except RuntimeError: + logger.exception("the application could not start") + finally: + logger.remove(sink_id) + + output = "".join(lines) + assert "configure_logger(" in output + assert "PermitConfig(pdp=" in output + assert SENTINEL not in output + assert SENTINEL not in str(config) + + +# loguru cannot remove a level once added, so this application runs in its own process. +CUSTOM_LEVEL_APP = f""" +import sys + +from loguru import logger + +from permit import PermitConnectionError +from permit.sync import Permit + +logger.remove() +logger.add(sys.stdout, serialize=True) +logger.level("audit", no=35) +url = sys.argv[1] +permit = Permit( + token="{SENTINEL}", api_url=url, pdp=url, log={{"enable": True, "level": "audit"}} +) +with permit.wait_for_sync(): + pass +try: + permit.check("user-1", "read", "document") +except PermitConnectionError: + pass +""" + + +def test_level_accepts_a_level_the_application_added( + httpserver: HTTPServer, tmp_path: Path +) -> None: + httpserver.expect_request("/allowed", method="POST").respond_with_data( + "PDP failure", status=500 + ) + app = tmp_path / "app.py" + app.write_text(CUSTOM_LEVEL_APP) + + result = subprocess.run( + [sys.executable, str(app), httpserver.url_for("").rstrip("/")], + capture_output=True, + text=True, + timeout=120, + check=False, + ) + + assert result.returncode == 0, result.stderr + # "audit" (35) sits between WARNING (30) and ERROR (40): only the ERROR record is kept. + [record] = [json.loads(line)["record"] for line in result.stdout.splitlines()] + assert record["level"]["name"] == "ERROR" + assert record["message"].startswith("[Permit] error in permit.check(") + assert SENTINEL not in result.stdout + result.stderr + + +@pytest.mark.parametrize( + ("log", "prefix"), + [ + pytest.param({}, "[Permit] ", id="default"), + pytest.param({"label": "acme-authz"}, "[acme-authz] ", id="custom"), + ], +) +async def test_label_prefixes_every_sdk_message( + httpserver: HTTPServer, app_sinks: AppSinks, log: dict[str, str], prefix: str +) -> None: + serve(httpserver) + + await use_async_client(Permit(make_config(httpserver, enable=True, level="debug", **log))) + + messages = [record["message"] for record in app_sinks.sdk_records()] + assert len(messages) > 3 + assert [message for message in messages if not message.startswith(prefix)] == [] + assert f"{prefix}{WAIT_FOR_SYNC_WARNING}" in app_sinks.stderr() + + +def test_an_empty_label_adds_no_prefix(httpserver: HTTPServer, app_sinks: AppSinks) -> None: + with SyncPermit(make_config(httpserver, enable=True, label="")).wait_for_sync(): + pass + + [record] = app_sinks.wait_for_sync_warnings() + assert record["message"].startswith(WAIT_FOR_SYNC_WARNING) + + +@pytest.mark.parametrize("token", ["", " "]) +def test_an_empty_api_key_redacts_nothing( + httpserver: HTTPServer, app_sinks: AppSinks, token: str +) -> None: + with SyncPermit(make_config(httpserver, token=token, enable=True)).wait_for_sync(): + pass + + [record] = app_sinks.wait_for_sync_warnings() + assert ( + record["message"] + == f"[Permit] {WAIT_FOR_SYNC_WARNING} but proxy_facts_via_pdp is disabled, ignoring..." + ) + + +def test_records_name_the_sdk_module_that_logged_them( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + with SyncPermit(make_config(httpserver, enable=True)).wait_for_sync(): + pass + + [record] = app_sinks.wait_for_sync_warnings() + assert (record["name"], record["function"]) == ("permit.permit", "wait_for_sync") + assert "| permit.permit:wait_for_sync:" in app_sinks.stderr() + + +@pytest.mark.parametrize("as_json", AS_JSON) +def test_log_as_json_leaves_the_format_to_the_application_sinks( + httpserver: HTTPServer, app_sinks: AppSinks, *, as_json: bool +) -> None: + with SyncPermit(make_config(httpserver, enable=True, json=as_json)).wait_for_sync(): + pass + + # One text line in the stderr sink and one JSON line in the JSON sink: the SDK + # neither adds a JSON sink of its own nor changes the application's. + [line] = [line for line in app_sinks.stderr().splitlines() if WAIT_FOR_SYNC_WARNING in line] + assert "| WARNING | permit.permit:wait_for_sync:" in line + assert len(app_sinks.wait_for_sync_warnings()) == 1 + + +DISABLED = [ + pytest.param({}, id="unset"), + pytest.param({"enable": False}, id="false"), + pytest.param( + {"enable": False, "level": "debug", "label": "x", "json": True}, id="false-with-options" + ), + pytest.param({"enable": False, "level": "not-a-level"}, id="false-unknown-level"), +] + + +@pytest.mark.parametrize("log", DISABLED) +async def test_async_client_with_logging_disabled_logs_nothing( + httpserver: HTTPServer, app_sinks: AppSinks, log: dict[str, Any] +) -> None: + serve(httpserver) + + await use_async_client(Permit(make_config(httpserver, **log))) + + assert app_sinks.everything() == "" + + +@pytest.mark.parametrize("log", DISABLED) +def test_sync_client_with_logging_disabled_logs_nothing( + httpserver: HTTPServer, app_sinks: AppSinks, log: dict[str, Any] +) -> None: + serve(httpserver) + + use_sync_client(SyncPermit(make_config(httpserver, **log))) + + assert app_sinks.everything() == "" + + +def test_the_client_created_last_decides_whether_the_sdk_logs( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + SyncPermit(make_config(httpserver)) + enabled = SyncPermit(make_config(httpserver, enable=True)) + with enabled.wait_for_sync(): + pass + assert len(app_sinks.wait_for_sync_warnings()) == 1 + + SyncPermit(make_config(httpserver)) + with enabled.wait_for_sync(): + pass + assert len(app_sinks.wait_for_sync_warnings()) == 1 + + +def test_an_enabled_client_keeps_a_disable_the_application_set_for_an_sdk_module( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + httpserver.expect_request("/allowed", method="POST").respond_with_json({"allow": True}) + logger.disable("permit.enforcement") + + permit = SyncPermit(make_config(httpserver, enable=True, level="debug")) + assert permit.check("user-1", "read", "document") + + modules = {record["name"] for record in app_sinks.sdk_records()} + assert "permit.permit" in modules + assert [module for module in modules if module.startswith("permit.enforcement")] == [] + + +def test_an_enabled_client_keeps_a_disable_the_application_set_for_the_sdk( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + logger.disable("permit") + + with SyncPermit(make_config(httpserver, enable=True)).wait_for_sync(): + pass + + assert app_sinks.sdk_records() == [] + + +def proxied_config(httpserver: HTTPServer, **log: Any) -> PermitConfig: + """A config that writes facts through the PDP, so `wait_for_sync` derives a client.""" + config = make_config(httpserver, **log) + config.proxy_facts_via_pdp = True + return config + + +def test_wait_for_sync_keeps_logging_off_after_a_disabled_client( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + proxied = SyncPermit(proxied_config(httpserver, enable=True)) + unproxied = SyncPermit(make_config(httpserver, enable=True)) + SyncPermit(make_config(httpserver)) + + with proxied.wait_for_sync(): + pass + with unproxied.wait_for_sync(): + pass + + assert app_sinks.sdk_records() == [] + + +def test_wait_for_sync_keeps_the_level_and_label_of_the_client_created_last( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + proxied = SyncPermit(proxied_config(httpserver, enable=True, level="debug", label="first")) + last = SyncPermit(make_config(httpserver, enable=True, level="warning", label="last")) + records_before = len(app_sinks.sdk_records()) + + with proxied.wait_for_sync(): + pass + with last.wait_for_sync(): + pass + + [record] = app_sinks.sdk_records()[records_before:] + assert record["message"].startswith(f"[last] {WAIT_FOR_SYNC_WARNING}") + + +@pytest.mark.parametrize( + "client_class", [pytest.param(Permit, id="async"), pytest.param(SyncPermit, id="sync")] +) +async def test_wait_for_sync_yields_a_client_that_waits_for_the_facts( + httpserver: HTTPServer, client_class: type[Permit] +) -> None: + serve(httpserver) + httpserver.expect_request(re.compile(r"/facts/tenants/.*"), method="DELETE").respond_with_data( + "", status=204 + ) + permit = client_class(proxied_config(httpserver)) + + with permit.wait_for_sync(timeout=3.0, policy="fail") as waiting: + assert type(waiting) is client_class + assert waiting.config.facts_sync_timeout == 3.0 + deleted = waiting.api.tenants.delete("tenant-1") + if client_class is Permit: + await deleted + deleted = permit.api.tenants.delete("tenant-2") + if client_class is Permit: + await deleted + + [waited, not_waited] = [ + request for request, _ in httpserver.log if request.path.startswith("/facts/") + ] + assert waited.path == "/facts/tenants/tenant-1" + assert (waited.headers.get("X-Wait-Timeout"), waited.headers.get("X-Timeout-Policy")) == ( + "3.0", + "fail", + ) + assert "X-Wait-Timeout" not in not_waited.headers + assert permit.config.facts_sync_timeout is None + + +def test_the_application_can_still_turn_the_sdk_records_on_itself( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + httpserver.expect_request("/allowed", method="POST").respond_with_json({"allow": True}) + permit = SyncPermit(make_config(httpserver)) + + logger.enable("permit") + assert permit.check("user-1", "read", "document") + + # No client enabled logging, so no level or label applies: the records are as before. + [record] = app_sinks.sdk_records() + assert record["level"]["name"] == "DEBUG" + assert record["message"].startswith("permit.check() response:") + + +def _next_handler_id() -> int: + """The id loguru gives the next sink: each `logger.add` takes the next one.""" + sink_id = logger.add(lambda _: None) + logger.remove(sink_id) + return sink_id + + +def test_creating_many_clients_adds_no_sinks(httpserver: HTTPServer, app_sinks: AppSinks) -> None: + first_free_id = _next_handler_id() + + clients = [ + client_class(make_config(httpserver, enable=True, json=True, label=f"client-{index}")) + for index in range(20) + for client_class in (Permit, SyncPermit) + ] + + assert _next_handler_id() == first_free_id + 1 + with clients[-1].wait_for_sync(): + pass + assert len(app_sinks.wait_for_sync_warnings()) == 1 + assert app_sinks.stderr().count(WAIT_FOR_SYNC_WARNING) == 1 From ec418761e406281bba17804492026d7e8adb28d9 Mon Sep 17 00:00:00 2001 From: eli Date: Tue, 27 Oct 2026 18:27:17 -0500 Subject: [PATCH 02/17] PER-16680: review follow-ups: scrub every raised error body, URL user info, wait_for_sync - handle_api_error scrubs the registered keys from the body it puts in an exception, text or JSON, so the REST API and the PDP's local API raise without them, as the enforcer already did. - The start-up line logs api_url and pdp without a user name or password. - wait_for_sync builds a client of the same class again, so a subclass's own setup runs, and keeps the process's log settings through the keep_log_settings context variable. - A secret shorter than 12 characters is not redacted, so a short test token doesn't mangle the SDK's text. - log.level takes a loguru severity number and surrounding whitespace; an unknown level is warned about once per process. - The SDK's enable/disable switch changes under a lock. - Drop sync.Permit.__init__, which only called super(). - README and docstrings match. Co-Authored-By: Claude Opus 5.5 --- README.md | 16 ++++--- permit/config.py | 6 +-- permit/exceptions.py | 20 +++++++-- permit/logger.py | 34 ++++++++++++-- permit/permit.py | 29 ++++++++---- permit/sync.py | 4 -- permit/utils/sdk_logger.py | 28 +++++++----- tests/test_fix_logging.py | 90 +++++++++++++++++++++++++++++++++++++- 8 files changed, 187 insertions(+), 40 deletions(-) diff --git a/README.md b/README.md index 01e3ed49..17089351 100644 --- a/README.md +++ b/README.md @@ -52,9 +52,10 @@ permit = Permit(token="", log={"enable": True, "level": "debug"}) - The SDK adds no loguru sink of its own. Its records go to the sinks your application has added, or to loguru's default stderr sink, in the format of those sinks. - `"enable": False` (the default) calls loguru's `logger.disable("permit")`. `"enable": True` - undoes that call, with `logger.enable("permit")`, only if an earlier client made it, so a - `logger.disable()` your application made for `permit` or one of its modules still - applies. When it does undo it, loguru also drops any `permit.*` module disable made since. + undoes that call, with `logger.enable("permit")`, only if an earlier client made it. + Otherwise a `logger.disable()` your application made for `permit` or one of its modules + still applies. When it does undo it, it also undoes your application's own + `logger.disable("permit")`, and loguru drops any `permit.*` module disable made since. - `level` (default `"info"`) is the lowest severity the SDK logs. Its records below it never reach a sink. Your application's own records are not affected. The SDK logs its HTTP requests and the PDP's responses at `"debug"`. With `"enable": True`, for a level name @@ -68,9 +69,12 @@ permit = Permit(token="", log={"enable": True, "level": "debug"}) level and the label, for every client in the process. `wait_for_sync()` creates no client: it yields a copy of the client it is called on. - The SDK replaces the API key of every client in the process with `[REDACTED]` in the - messages it logs and in the PDP error bodies it puts in a `PermitConnectionError`, so a - PDP that echoes the key back does not expose it. A user name and password written into - the `api_url` or `pdp` URL are not replaced: the SDK logs its request URLs at `"debug"`. + messages it logs and in the error bodies it puts in the exceptions it raises, so an API + or PDP that echoes the key back does not expose it. A key shorter than 12 characters is + not replaced. The client's start-up line logs `api_url` and `pdp` without any user name + or password in them. +- `level` also takes a loguru severity number, such as `10` for DEBUG. An unknown name is + warned about once per process. ## Deprecations diff --git a/permit/config.py b/permit/config.py index 490c6576..7c95a461 100644 --- a/permit/config.py +++ b/permit/config.py @@ -22,9 +22,9 @@ class LoggerConfig(BaseModel): the level and the label, for every client in the process. Whatever these settings, the SDK replaces the API key of every client in the process - with `[REDACTED]` in the messages it logs and in the PDP error bodies it puts in a - `PermitConnectionError`. A user name and password written into the `api_url` or `pdp` - URL are not replaced. + with `[REDACTED]` in the messages it logs and in the error bodies it puts in the + exceptions it raises. The client's start-up line logs `api_url` and `pdp` without a user + name or password. """ enable: bool = Field( diff --git a/permit/exceptions.py b/permit/exceptions.py index 319b1dac..0ddeaaee 100644 --- a/permit/exceptions.py +++ b/permit/exceptions.py @@ -2,7 +2,7 @@ import warnings from collections.abc import Awaitable, Callable, Coroutine from http import HTTPStatus -from typing import TYPE_CHECKING, Any, TypeVar +from typing import TYPE_CHECKING, Any, TypeVar, cast import aiohttp from typing_extensions import ParamSpec, deprecated @@ -229,6 +229,20 @@ class PermitNotFoundError(PermitApiDetailedError): """Object not found response from the Permit API.""" +_JsonT = TypeVar("_JsonT") + + +def _scrubbed(value: _JsonT) -> _JsonT: + """`value`, a decoded JSON body, with every registered API key replaced in its strings.""" + if isinstance(value, str): + return cast("_JsonT", sdk_logger.scrub(value)) + if isinstance(value, list): + return cast("_JsonT", [_scrubbed(item) for item in value]) + if isinstance(value, dict): + return cast("_JsonT", {key: _scrubbed(item) for key, item in value.items()}) + return value + + async def handle_api_error(response: aiohttp.ClientResponse) -> None: """Raise the matching SDK exception if `response` has a non-2xx status. @@ -246,9 +260,9 @@ async def handle_api_error(response: aiohttp.ClientResponse) -> None: return try: - json = await response.json() + json = _scrubbed(await response.json()) except aiohttp.ContentTypeError as e: - text = await response.text() + text = sdk_logger.scrub(await response.text()) raise PermitApiError(response, {"details": text}) from e if response.status == HTTPStatus.UNPROCESSABLE_ENTITY: diff --git a/permit/logger.py b/permit/logger.py index 48f35113..e1bd732b 100644 --- a/permit/logger.py +++ b/permit/logger.py @@ -1,4 +1,6 @@ import contextlib +import contextvars +import threading from loguru import logger @@ -10,6 +12,17 @@ # The names Python's logging module also accepts, and the ones the Node SDK's logger uses. _LEVEL_ALIASES = {"WARN": "WARNING", "FATAL": "CRITICAL"} +# Set while a client derives another from itself (`Permit.wait_for_sync`): the derived +# client keeps the process's log settings instead of applying its own again. +keep_log_settings: contextvars.ContextVar[bool] = contextvars.ContextVar( + "permit_keep_log_settings", default=False +) + +# The unknown level names already warned about, so a process that creates a client per +# request warns once per name. +_warned_levels: set[str] = set() +_warned_levels_lock = threading.Lock() + def configure_logger(config: PermitConfig) -> None: """Apply the `log` settings of `config` to the SDK's log records. @@ -31,22 +44,31 @@ def configure_logger(config: PermitConfig) -> None: then `logger.add(sys.stderr, serialize=True)`. Whatever the settings, the API key in `config.token` is replaced with `[REDACTED]` in - every message the SDK logs and in the PDP error bodies it puts in a - `PermitConnectionError`. + every message the SDK logs and in the error bodies it puts in the exceptions it raises. - An unknown `log.level` does not fail client creation: the SDK logs a warning that names - the value and uses INFO. + `log.level` is a level name, in any case, or a loguru severity number. An unknown one + does not fail client creation: the SDK logs a warning that names the value, once per + process, and uses INFO. + + While `keep_log_settings` is set (`Permit.wait_for_sync` deriving a client), only the + key is registered for redaction: the process's log settings stay as they are. Args: config: The SDK configuration. """ sdk_logger.redact(config.token) + if keep_log_settings.get(): + return if not config.log.enable: sdk_logger.disable() return level_no = _level_no(config.log.level) if level_no is None: sdk_logger.enable(min_level_no=logger.level("INFO").no, label=config.log.label) + with _warned_levels_lock: + if config.log.level in _warned_levels: + return + _warned_levels.add(config.log.level) sdk_logger.warning( f"Unknown log level {config.log.level!r} in the Permit SDK config (log.level), " "so the SDK logs at INFO. Use trace, debug, info, success, warning, error or " @@ -57,6 +79,10 @@ def configure_logger(config: PermitConfig) -> None: def _level_no(level: str) -> int | None: + level = level.strip() + # A severity number, as loguru accepts it (pydantic turns `10` into "10"). + if level.isdigit(): + return int(level) upper = level.upper() # loguru's level names are case-sensitive: try the name as given first, so a level the # application added in lower case is found, then the upper-case name of a built-in one. diff --git a/permit/permit.py b/permit/permit.py index a636a05c..7383ff53 100644 --- a/permit/permit.py +++ b/permit/permit.py @@ -1,7 +1,7 @@ -import copy from collections.abc import Generator from contextlib import contextmanager from typing import Any, Literal +from urllib.parse import urlsplit, urlunsplit from typing_extensions import Self @@ -16,12 +16,22 @@ User, ) from permit.enforcement.interfaces import AuthorizedUsersResult -from permit.logger import configure_logger +from permit.logger import configure_logger, keep_log_settings from permit.pdp_api.pdp_api_client import PermitPdpApiClient from permit.utils.context import Context from permit.utils.sdk_logger import sdk_logger +def _without_userinfo(url: str) -> str: + """`url` without a user name or password, which a proxy URL may carry.""" + parts = urlsplit(url) + if parts.username is None and parts.password is None: + return url + host = parts.hostname or "" + netloc = f"{host}:{parts.port}" if parts.port is not None else host + return urlunsplit(parts._replace(netloc=netloc)) + + class Permit: """The Permit SDK client (asyncio): authorization checks and the Permit REST API. @@ -37,7 +47,8 @@ def __init__(self, config: PermitConfig | None = None, **options: Any) -> None: configure_logger(self._config) self._connect() sdk_logger.debug( - f"Permit SDK initialized: api_url={self._config.api_url}, pdp={self._config.pdp}" + f"Permit SDK initialized: api_url={_without_userinfo(self._config.api_url)}, " + f"pdp={_without_userinfo(self._config.pdp)}" ) def _connect(self) -> None: @@ -93,11 +104,13 @@ def wait_for_sync( contextualized_config.facts_sync_timeout = timeout if policy is not None: contextualized_config.facts_sync_timeout_policy = policy - # A copy of this client that sends its requests with the new config. Creating a new - # client instead would apply its log settings to the whole process again. - waiting: Self = copy.copy(self) - waiting._config = contextualized_config - waiting._connect() + # A client of this class, so a subclass's own setup runs, that keeps the process's + # log settings: applying this client's again would undo a client created since. + token = keep_log_settings.set(True) + try: + waiting = self.__class__(contextualized_config) + finally: + keep_log_settings.reset(token) yield waiting @property diff --git a/permit/sync.py b/permit/sync.py index 84bc0d7b..7c197e93 100644 --- a/permit/sync.py +++ b/permit/sync.py @@ -2,7 +2,6 @@ from permit.api.elements import SyncElementsApi from permit.api.sync_api_client import SyncPermitApiClient -from permit.config import PermitConfig from permit.enforcement.enforcer import ( Action, CheckQuery, @@ -29,9 +28,6 @@ class Permit(AsyncPermit): is not given. """ - def __init__(self, config: PermitConfig | None = None, **options: Any) -> None: - super().__init__(config, **options) - def _connect(self) -> None: self._enforcer = SyncEnforcer(self._config) # type: ignore[assignment] self._api = SyncPermitApiClient(self._config) # type: ignore[assignment] diff --git a/permit/utils/sdk_logger.py b/permit/utils/sdk_logger.py index 07faed11..9ede227b 100644 --- a/permit/utils/sdk_logger.py +++ b/permit/utils/sdk_logger.py @@ -3,6 +3,9 @@ from loguru import logger REDACTED = "[REDACTED]" +# A secret shorter than this is not redacted: replacing a short value such as "token" in +# every message would mangle the SDK's own text. Permit API keys are far longer. +MIN_SECRET_LENGTH = 12 # The package whose records loguru's logger.enable() and logger.disable() switch on and off. PACKAGE = "permit" @@ -25,6 +28,9 @@ def __init__(self) -> None: self._label = "" # Whether `disable` called logger.disable("permit") after the last `enable`. self._disabled_package = False + # Held while the loguru switch and `_disabled_package` change together, so two + # clients created at once in different threads leave them consistent. + self._switch_lock = threading.Lock() self._secrets_lock = threading.Lock() # Longest first: where one secret contains another, such as a key and a prefix of # it, the whole of the longer one is replaced, not just the shorter part. Replaced, @@ -34,8 +40,9 @@ def __init__(self) -> None: def disable(self) -> None: """Stop loguru from passing on any record of the package: `logger.disable("permit")`.""" - logger.disable(PACKAGE) - self._disabled_package = True + with self._switch_lock: + logger.disable(PACKAGE) + self._disabled_package = True def enable(self, *, min_level_no: int, label: str) -> None: """Keep the records from `min_level_no` up, with `label` before each message. @@ -49,11 +56,12 @@ def enable(self, *, min_level_no: int, label: str) -> None: min_level_no: The loguru severity number below which records are dropped. label: The text put in brackets before each message; an empty string adds none. """ - self._min_level_no = min_level_no - self._label = label - if self._disabled_package: - logger.enable(PACKAGE) - self._disabled_package = False + with self._switch_lock: + self._min_level_no = min_level_no + self._label = label + if self._disabled_package: + logger.enable(PACKAGE) + self._disabled_package = False def redact(self, secret: str) -> None: """Replace `secret` with `[REDACTED]` in every record logged from now on. @@ -63,11 +71,11 @@ def redact(self, secret: str) -> None: that echoes the key back has stripped. Args: - secret: A credential, such as an API key. A secret that is empty or only - whitespace is ignored. + secret: A credential, such as an API key. A secret shorter than + `MIN_SECRET_LENGTH` without its surrounding whitespace is ignored. """ trimmed = secret.strip() - if not trimmed: + if len(trimmed) < MIN_SECRET_LENGTH: return with self._secrets_lock: new = {secret, trimmed}.difference(self._secrets) diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py index 5422f424..0790dec7 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -11,7 +11,7 @@ import subprocess import sys import types -from collections.abc import Iterator +from collections.abc import Callable, Iterator from dataclasses import dataclass, field from pathlib import Path from typing import Any @@ -23,7 +23,7 @@ from permit import Permit, PermitConfig from permit.enforcement.enforcer import CheckQuery -from permit.exceptions import PermitConnectionError +from permit.exceptions import PermitApiError, PermitConnectionError from permit.sync import Permit as SyncPermit from permit.utils.sdk_logger import REDACTED, SdkLogger, sdk_logger @@ -693,3 +693,89 @@ def test_creating_many_clients_adds_no_sinks(httpserver: HTTPServer, app_sinks: pass assert len(app_sinks.wait_for_sync_warnings()) == 1 assert app_sinks.stderr().count(WAIT_FOR_SYNC_WARNING) == 1 + + +def echo_the_key_as_json(request: Request) -> Response: + """An API that rejects the request and echoes the key it was sent, in a JSON body.""" + body = {"detail": f"rejected key: {request.headers['Authorization']}", "error_code": "x"} + return Response(json.dumps(body), status=403, content_type="application/json") + + +@pytest.mark.parametrize("handler", [echo_the_key, echo_the_key_as_json], ids=["text", "json"]) +async def test_api_and_pdp_api_errors_do_not_hold_an_echoed_key( + httpserver: HTTPServer, handler: Callable[[Request], Response] +) -> None: + """The REST API and the PDP's local API raise through `handle_api_error`.""" + serve(httpserver) + httpserver.expect_request(f"{USERS}/user-2", method="GET").respond_with_handler(handler) + httpserver.expect_request("/local/role_assignments", method="GET").respond_with_handler(handler) + permit = Permit(make_config(httpserver)) + + raised: list[BaseException] = [] + for call in (permit.api.users.get("user-2"), permit.pdp_api.role_assignments.list()): + with pytest.raises((PermitApiError, PermitConnectionError)) as caught: + await call + raised.append(caught.value) + + for error in raised: + assert SENTINEL not in str(error) + assert SENTINEL not in repr(error) + assert REDACTED in str(error) + + +def test_the_init_line_leaves_out_the_url_user_and_password( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + url = httpserver.url_for("").rstrip("/").replace("://", "://proxy-user:proxy-password@") + config = PermitConfig( + token=SENTINEL, api_url=url, pdp=url, log={"enable": True, "level": "debug"} + ) + + SyncPermit(config) + + [record] = [r for r in app_sinks.sdk_records() if "SDK initialized" in r["message"]] + assert "proxy-password" not in record["message"] + assert "proxy-user" not in record["message"] + assert httpserver.url_for("").rstrip("/") in record["message"] + + +def test_wait_for_sync_runs_a_subclass_s_own_setup(httpserver: HTTPServer) -> None: + class CustomPermit(SyncPermit): + def __init__(self, config: PermitConfig) -> None: + super().__init__(config) + self.custom = True + + permit = CustomPermit(proxied_config(httpserver)) + with permit.wait_for_sync() as waiting: + assert type(waiting) is CustomPermit + assert waiting.custom is True + + +def test_a_short_token_is_not_redacted_from_the_sdk_s_text() -> None: + redactor = SdkLogger() + redactor.redact("token") + redactor.redact(" permit ") + + assert redactor.scrub("bad token for permit.check()") == "bad token for permit.check()" + + +@pytest.mark.parametrize("level", ["10", " debug ", "DEBUG"]) +def test_a_numeric_or_padded_level_is_read( + httpserver: HTTPServer, app_sinks: AppSinks, level: str +) -> None: + httpserver.expect_request("/allowed", method="POST").respond_with_json({"allow": True}) + permit = SyncPermit(make_config(httpserver, enable=True, level=level)) + + assert permit.check("user-1", "read", "document") + + levels = {record["level"]["name"] for record in app_sinks.sdk_records()} + assert "DEBUG" in levels + assert "WARNING" not in levels + + +def test_an_unknown_level_is_warned_about_once(httpserver: HTTPServer, app_sinks: AppSinks) -> None: + for _ in range(3): + SyncPermit(make_config(httpserver, enable=True, level="verbose-once")) + + warnings = [r for r in app_sinks.sdk_records() if "Unknown log level" in r["message"]] + assert len(warnings) == 1 From 65cc6705b58f303f5ffdf06f013434195960cc1a Mon Sep 17 00:00:00 2001 From: eli Date: Wed, 28 Oct 2026 13:05:25 -0500 Subject: [PATCH 03/17] PER-16680: second review pass: scrub carried request headers, safe URL helper - aiohttp keeps the request's headers, Authorization included, on the ClientResponse and ClientResponseError the SDK's exceptions carry (original_error, response, the cause), and their repr prints them. scrub_request_info replaces every registered key there before an exception holds them, including the response's cached request_info. - without_userinfo moves to permit.utils.sdk_logger. It never raises (a bad port no longer fails client creation, an unparseable URL shows as ) and keeps IPv6 brackets. - PDP error messages show the PDP URL without a user name or password. - README: wait_for_sync builds a new client of the same class; what the key is replaced in. - Tests: REST and PDP errors for a non-JSON answer (200 and 502) and for an echoed key carry no key in their cause, context, original_error or response; without_userinfo cases. Co-Authored-By: Claude Opus 5.5 --- README.md | 14 ++++--- permit/enforcement/enforcer.py | 18 +++++---- permit/exceptions.py | 35 +++++++++++++++++ permit/permit.py | 17 ++------- permit/utils/sdk_logger.py | 16 ++++++++ tests/test_fix_logging.py | 68 +++++++++++++++++++++++++++++++++- 6 files changed, 139 insertions(+), 29 deletions(-) diff --git a/README.md b/README.md index 17089351..0e5aa51a 100644 --- a/README.md +++ b/README.md @@ -66,13 +66,15 @@ permit = Permit(token="", log={"enable": True, "level": "debug"}) Added next to the default sink, it prints every record a second time. - loguru's logger is process-wide, so these settings are too: the client created last decides whether the SDK logs, and the last one created with `"enable": True` decides the - level and the label, for every client in the process. `wait_for_sync()` creates no - client: it yields a copy of the client it is called on. + level and the label, for every client in the process. `wait_for_sync()` builds a new + client of the same class, but keeps the process's log settings as they are. - The SDK replaces the API key of every client in the process with `[REDACTED]` in the - messages it logs and in the error bodies it puts in the exceptions it raises, so an API - or PDP that echoes the key back does not expose it. A key shorter than 12 characters is - not replaced. The client's start-up line logs `api_url` and `pdp` without any user name - or password in them. + messages it logs, in the error bodies it puts in the exceptions it raises, and in the + request headers of the aiohttp response or error those exceptions carry + (`original_error`, `response`, the cause), so neither an API or PDP that echoes the key + back nor an error tracker that records exceptions exposes it. A key shorter than 12 + characters is not replaced. The client's start-up line and the PDP error messages show + `api_url` and `pdp` without any user name or password in them. - `level` also takes a loguru severity number, such as `10` for DEBUG. An unknown name is warned about once per process. diff --git a/permit/enforcement/enforcer.py b/permit/enforcement/enforcer.py index c9d51027..01a5fb59 100644 --- a/permit/enforcement/enforcer.py +++ b/permit/enforcement/enforcer.py @@ -13,7 +13,7 @@ from permit.utils.context import Context, ContextStore from permit.utils.dicts import deep_merge from permit.utils.pydantic_version import PYDANTIC_VERSION -from permit.utils.sdk_logger import sdk_logger +from permit.utils.sdk_logger import sdk_logger, without_userinfo from permit.utils.sync import SyncClass if TYPE_CHECKING: @@ -100,6 +100,8 @@ def __init__(self, config: PermitConfig) -> None: "Authorization": f"Bearer {self._config.token}", } self._base_url = self._config.pdp + # The PDP URL as error messages show it: a proxy URL's user and password left out. + self._shown_pdp_url = without_userinfo(self._config.pdp) @property def context_store(self) -> ContextStore: @@ -180,7 +182,7 @@ async def authorized_users( f"as the cloud PDP is not compatible with these kinds " f"of policies.\n" f"Also, please check your configuration and " - f"make sure it's running at {self._base_url} " + f"make sure it's running at {self._shown_pdp_url} " f"and accepting requests.\n" f"Read more about setting up the PDP at {SETUP_PDP_DOCS_LINK}" ) @@ -197,7 +199,7 @@ async def authorized_users( ) msg = ( f"Permit SDK got unexpected status code: {response.status} " - f"from the PDP at {self._base_url}.\nResponse body: {error_body}\n" + f"from the PDP at {self._shown_pdp_url}.\nResponse body: {error_body}\n" f"The PDP is reachable, so this is a rejected request rather than a " f"connectivity problem -- a 401/403 usually means the PDP was started " f"with a different API key than the SDK is using.\n" @@ -222,7 +224,7 @@ async def authorized_users( msg = ( f"Permit SDK got error: {err}, and cannot connect to the PDP container.\n" f"Please check your configuration and make sure it's running at " - f"{self._base_url} and accepting requests.\n " + f"{self._shown_pdp_url} and accepting requests.\n " f"Read more about setting up the PDP at {SETUP_PDP_DOCS_LINK}" ) raise PermitConnectionError( @@ -418,7 +420,7 @@ async def check( f"as the cloud PDP is not compatible with these kinds " f"of policies.\n" f"Also, please check your configuration and make sure it's running " - f"at {self._base_url} and accepting requests.\n" + f"at {self._shown_pdp_url} and accepting requests.\n" f"Read more about setting up the PDP at {SETUP_PDP_DOCS_LINK}" ) raise PermitConnectionError(msg) @@ -435,7 +437,7 @@ async def check( ) msg = ( f"Permit SDK got unexpected status code: {response.status} " - f"from the PDP at {self._base_url}.\nResponse body: {error_body}\n" + f"from the PDP at {self._shown_pdp_url}.\nResponse body: {error_body}\n" f"The PDP is reachable, so this is a rejected request rather than a " f"connectivity problem -- a 401/403 usually means the PDP was started " f"with a different API key than the SDK is using.\n" @@ -462,7 +464,7 @@ async def check( f"Permit SDK got error: {err}, \n" f"and cannot connect to the PDP container, please check your configuration " f"and make sure it's " - f"running at {self._base_url} and accepting requests. \n" + f"running at {self._shown_pdp_url} and accepting requests. \n" f"Read more about setting up the PDP at {SETUP_PDP_DOCS_LINK}" ) raise PermitConnectionError( @@ -535,7 +537,7 @@ async def get_user_permissions( f"Permit SDK got error: {err}, \n" f"and cannot connect to the PDP container, please check your configuration " f"and make sure it's " - f"running at {self._base_url} and accepting requests. \n" + f"running at {self._shown_pdp_url} and accepting requests. \n" f"Read more about setting up the PDP at {SETUP_PDP_DOCS_LINK}" ) raise PermitConnectionError( diff --git a/permit/exceptions.py b/permit/exceptions.py index 0ddeaaee..f62d5df1 100644 --- a/permit/exceptions.py +++ b/permit/exceptions.py @@ -5,6 +5,7 @@ from typing import TYPE_CHECKING, Any, TypeVar, cast import aiohttp +from multidict import CIMultiDict, CIMultiDictProxy from typing_extensions import ParamSpec, deprecated from permit.utils.pydantic_version import PYDANTIC_VERSION @@ -54,6 +55,8 @@ class PermitConnectionError(PermitException): # type: ignore[deprecated] # kept def __init__(self, message: str, *, error: aiohttp.ClientError | None = None) -> None: super().__init__(message) + if error is not None: + scrub_request_info(error) self.original_error = error @@ -85,6 +88,7 @@ def __init__( body: dict[str, Any] | None = None, ) -> None: super().__init__() + scrub_request_info(response) self._response = response self._body = body @@ -243,6 +247,36 @@ def _scrubbed(value: _JsonT) -> _JsonT: return value +def scrub_request_info(holder: object) -> None: + """Replace every client's API key in the request headers `holder` keeps. + + aiohttp keeps the request's headers, `Authorization` included, on a + `ClientResponse` and a `ClientResponseError` (`request_info`), and its `repr` prints + them. The SDK puts such objects in the exceptions it raises (`original_error`, + `response`, the exception's cause), so it scrubs them first. Anything else is left + as it is. + + Args: + holder: An aiohttp response or client error. + """ + info = getattr(holder, "request_info", None) + if not isinstance(info, aiohttp.RequestInfo): + return + headers = CIMultiDict((name, sdk_logger.scrub(value)) for name, value in info.headers.items()) + if headers == info.headers: + return + scrubbed = aiohttp.RequestInfo(info.url, info.method, CIMultiDictProxy(headers), info.real_url) + if isinstance(holder, aiohttp.ClientResponse): + # `request_info` is a read-only property over `_request_info`, cached once read + # (aiohttp's `reify`): replace both. tests/test_fix_logging.py checks the result. + holder._request_info = scrubbed # noqa: SLF001 + cache = getattr(holder, "_cache", None) + if isinstance(cache, dict) and "request_info" in cache: + cache["request_info"] = scrubbed + else: + holder.request_info = scrubbed # type: ignore[attr-defined] + + async def handle_api_error(response: aiohttp.ClientResponse) -> None: """Raise the matching SDK exception if `response` has a non-2xx status. @@ -262,6 +296,7 @@ async def handle_api_error(response: aiohttp.ClientResponse) -> None: try: json = _scrubbed(await response.json()) except aiohttp.ContentTypeError as e: + scrub_request_info(e) text = sdk_logger.scrub(await response.text()) raise PermitApiError(response, {"details": text}) from e diff --git a/permit/permit.py b/permit/permit.py index 7383ff53..7c403ed3 100644 --- a/permit/permit.py +++ b/permit/permit.py @@ -1,7 +1,6 @@ from collections.abc import Generator from contextlib import contextmanager from typing import Any, Literal -from urllib.parse import urlsplit, urlunsplit from typing_extensions import Self @@ -19,17 +18,7 @@ from permit.logger import configure_logger, keep_log_settings from permit.pdp_api.pdp_api_client import PermitPdpApiClient from permit.utils.context import Context -from permit.utils.sdk_logger import sdk_logger - - -def _without_userinfo(url: str) -> str: - """`url` without a user name or password, which a proxy URL may carry.""" - parts = urlsplit(url) - if parts.username is None and parts.password is None: - return url - host = parts.hostname or "" - netloc = f"{host}:{parts.port}" if parts.port is not None else host - return urlunsplit(parts._replace(netloc=netloc)) +from permit.utils.sdk_logger import sdk_logger, without_userinfo class Permit: @@ -47,8 +36,8 @@ def __init__(self, config: PermitConfig | None = None, **options: Any) -> None: configure_logger(self._config) self._connect() sdk_logger.debug( - f"Permit SDK initialized: api_url={_without_userinfo(self._config.api_url)}, " - f"pdp={_without_userinfo(self._config.pdp)}" + f"Permit SDK initialized: api_url={without_userinfo(self._config.api_url)}, " + f"pdp={without_userinfo(self._config.pdp)}" ) def _connect(self) -> None: diff --git a/permit/utils/sdk_logger.py b/permit/utils/sdk_logger.py index 9ede227b..d3464c66 100644 --- a/permit/utils/sdk_logger.py +++ b/permit/utils/sdk_logger.py @@ -1,4 +1,5 @@ import threading +from urllib.parse import urlsplit, urlunsplit from loguru import logger @@ -119,4 +120,19 @@ def _log(self, level: str, message: str) -> None: logger.opt(depth=2).log(level, message) +def without_userinfo(url: str) -> str: + """`url` without a user name or password, which a proxy URL may carry. + + For a log line or an exception message: it never raises, and a URL it can't parse + comes back as ``. + """ + try: + parts = urlsplit(url) + except ValueError: + return "" + if "@" not in parts.netloc: + return url + return urlunsplit(parts._replace(netloc=parts.netloc.rpartition("@")[2])) + + sdk_logger = SdkLogger() diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py index 0790dec7..36152d44 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -25,7 +25,7 @@ from permit.enforcement.enforcer import CheckQuery from permit.exceptions import PermitApiError, PermitConnectionError from permit.sync import Permit as SyncPermit -from permit.utils.sdk_logger import REDACTED, SdkLogger, sdk_logger +from permit.utils.sdk_logger import REDACTED, SdkLogger, sdk_logger, without_userinfo SENTINEL = "permit_key_SENTINEL_9f8e7d6c5b4a39281706f5e4d3c2b1a0" ORG_ID = "00000000-0000-4000-8000-00000000000a" @@ -721,6 +721,72 @@ async def test_api_and_pdp_api_errors_do_not_hold_an_echoed_key( assert SENTINEL not in str(error) assert SENTINEL not in repr(error) assert REDACTED in str(error) + assert_holds_no_key(error) + + +def assert_holds_no_key(error: BaseException) -> None: + """Assert neither `error` nor the aiohttp objects it carries print the key. + + Those are its cause and context, `original_error`, and a `PermitApiError`'s response. + """ + carried = [ + error.__cause__, + error.__context__, + getattr(error, "original_error", None), + getattr(error, "_response", None), + ] + for value in carried: + assert SENTINEL not in repr(value) + info = getattr(value, "request_info", None) + if info is not None: + assert SENTINEL not in repr(info) + assert SENTINEL not in str(dict(info.headers)) + + +@pytest.mark.parametrize("status", [200, 502]) +async def test_a_non_json_answer_raises_without_the_key_in_its_request_headers( + httpserver: HTTPServer, status: int +) -> None: + """An answer that isn't JSON raises without the key in its request headers. + + aiohttp keeps the request's headers on the error it raises for it. The SDK's + exception, its cause and `original_error` don't print the key. + """ + # Not `serve`, which already answers /allowed with JSON. + httpserver.expect_request("/v2/api-key/scope", method="GET").respond_with_json( + {"organization_id": ORG_ID, "project_id": PROJECT_ID, "environment_id": ENV_ID} + ) + httpserver.expect_request(f"{USERS}/user-3", method="GET").respond_with_data( + "bad gateway", status=status, content_type="text/html" + ) + httpserver.expect_request("/allowed", method="POST").respond_with_data( + "proxy", status=200, content_type="text/html" + ) + permit = Permit(make_config(httpserver)) + + raised: list[BaseException] = [] + for call in (permit.api.users.get("user-3"), permit.check("user-1", "read", "document")): + with pytest.raises((PermitApiError, PermitConnectionError)) as caught: + await call + raised.append(caught.value) + + assert any(error.__cause__ is not None for error in raised) + for error in raised: + assert_holds_no_key(error) + + +@pytest.mark.parametrize( + ("url", "shown"), + [ + ("http://user:secret@pdp.example.com:7766/x", "http://pdp.example.com:7766/x"), + ("http://user:secret@[::1]:7766", "http://[::1]:7766"), + ("http://user:secret@pdp.example.com:99999", "http://pdp.example.com:99999"), + ("http://pdp.example.com:7766", "http://pdp.example.com:7766"), + ("http://[::1", ""), + ], +) +def test_without_userinfo_never_raises(url: str, shown: str) -> None: + assert without_userinfo(url) == shown def test_the_init_line_leaves_out_the_url_user_and_password( From 9758ab58ea08b632049943e7290fed0b6e6ff662 Mon Sep 17 00:00:00 2001 From: eli Date: Wed, 28 Oct 2026 14:37:28 -0500 Subject: [PATCH 04/17] PER-16680: scrub JSON object keys and the labelled log line - handle_api_error's JSON scrubber replaces registered keys in object keys as well as values, so an error body that uses the key as a key doesn't expose it. - The SDK logger scrubs the message after the label is added, so a key placed in log.label is replaced too. - Tests: a key echoed as a JSON object key; a key in the label. Co-Authored-By: Claude Opus 5.5 --- permit/exceptions.py | 10 ++++++++-- permit/utils/sdk_logger.py | 3 ++- tests/test_fix_logging.py | 31 +++++++++++++++++++++++++++++++ 3 files changed, 41 insertions(+), 3 deletions(-) diff --git a/permit/exceptions.py b/permit/exceptions.py index f62d5df1..a6039e46 100644 --- a/permit/exceptions.py +++ b/permit/exceptions.py @@ -237,13 +237,19 @@ class PermitNotFoundError(PermitApiDetailedError): def _scrubbed(value: _JsonT) -> _JsonT: - """`value`, a decoded JSON body, with every registered API key replaced in its strings.""" + """Return `value`, a decoded JSON body, with every registered API key replaced. + + Strings are scrubbed wherever they are, object keys included. + """ if isinstance(value, str): return cast("_JsonT", sdk_logger.scrub(value)) if isinstance(value, list): return cast("_JsonT", [_scrubbed(item) for item in value]) if isinstance(value, dict): - return cast("_JsonT", {key: _scrubbed(item) for key, item in value.items()}) + return cast( + "_JsonT", + {_scrubbed(key): _scrubbed(item) for key, item in value.items()}, + ) return value diff --git a/permit/utils/sdk_logger.py b/permit/utils/sdk_logger.py index d3464c66..8a38f141 100644 --- a/permit/utils/sdk_logger.py +++ b/permit/utils/sdk_logger.py @@ -111,9 +111,10 @@ def error(self, message: str) -> None: def _log(self, level: str, message: str) -> None: if logger.level(level).no < self._min_level_no: return - message = self.scrub(message) if self._label: message = f"[{self._label}] {message}" + # After the label goes on, so a key in the label is replaced too. + message = self.scrub(message) # depth=2 skips this method and the one that called it, so loguru attributes the # record to the SDK module that logged it. The message goes without arguments, so # loguru does not call str.format on it and braces in it are kept as they are. diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py index 36152d44..4fb2b8d7 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -845,3 +845,34 @@ def test_an_unknown_level_is_warned_about_once(httpserver: HTTPServer, app_sinks warnings = [r for r in app_sinks.sdk_records() if "Unknown log level" in r["message"]] assert len(warnings) == 1 + + +def echo_the_key_as_a_json_object_key(request: Request) -> Response: + """An API that rejects the request and puts the key it was sent in an object key.""" + body = {"detail": {request.headers["Authorization"]: "rejected"}, "error_code": "x"} + return Response(json.dumps(body), status=403, content_type="application/json") + + +async def test_an_echoed_key_in_a_json_object_key_is_redacted(httpserver: HTTPServer) -> None: + serve(httpserver) + httpserver.expect_request(f"{USERS}/user-4", method="GET").respond_with_handler( + echo_the_key_as_a_json_object_key + ) + permit = Permit(make_config(httpserver)) + + with pytest.raises(PermitApiError) as caught: + await permit.api.users.get("user-4") + + assert SENTINEL not in str(caught.value) + assert SENTINEL not in repr(caught.value.details) + + +def test_a_key_in_the_label_is_redacted(httpserver: HTTPServer, app_sinks: AppSinks) -> None: + config = make_config(httpserver, enable=True, level="debug", label=f"app {SENTINEL}") + + SyncPermit(config) + + records = app_sinks.sdk_records() + assert records + for record in records: + assert SENTINEL not in record["message"] From fbc59c043782d2b6a12245b6410019d41f03fdd9 Mon Sep 17 00:00:00 2001 From: eli Date: Wed, 28 Oct 2026 14:51:33 -0500 Subject: [PATCH 05/17] PER-16680: scrub the request info aiohttp keeps in an error's args and redirect history A ClientResponseError keeps its RequestInfo as args[0] as well as in request_info, and the redirect responses in its (or a response's) history keep their own. scrub_request_info replaces the key in all of them. Test: neither the carried objects nor their args print the key. Co-Authored-By: Claude Opus 5.5 --- permit/exceptions.py | 10 ++++++++-- tests/test_fix_logging.py | 1 + 2 files changed, 9 insertions(+), 2 deletions(-) diff --git a/permit/exceptions.py b/permit/exceptions.py index a6039e46..81c4ca80 100644 --- a/permit/exceptions.py +++ b/permit/exceptions.py @@ -257,14 +257,18 @@ def scrub_request_info(holder: object) -> None: """Replace every client's API key in the request headers `holder` keeps. aiohttp keeps the request's headers, `Authorization` included, on a - `ClientResponse` and a `ClientResponseError` (`request_info`), and its `repr` prints - them. The SDK puts such objects in the exceptions it raises (`original_error`, + `ClientResponse` and a `ClientResponseError` (`request_info`, which the error also + keeps as `args[0]`), and on the redirect responses in their `history`; their `repr` + prints them. The SDK puts such objects in the exceptions it raises (`original_error`, `response`, the exception's cause), so it scrubs them first. Anything else is left as it is. Args: holder: An aiohttp response or client error. """ + for redirect in getattr(holder, "history", None) or (): + if redirect is not holder: + scrub_request_info(redirect) info = getattr(holder, "request_info", None) if not isinstance(info, aiohttp.RequestInfo): return @@ -281,6 +285,8 @@ def scrub_request_info(holder: object) -> None: cache["request_info"] = scrubbed else: holder.request_info = scrubbed # type: ignore[attr-defined] + if isinstance(holder, BaseException): + holder.args = tuple(scrubbed if arg is info else arg for arg in holder.args) async def handle_api_error(response: aiohttp.ClientResponse) -> None: diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py index 4fb2b8d7..86d9db2a 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -737,6 +737,7 @@ def assert_holds_no_key(error: BaseException) -> None: ] for value in carried: assert SENTINEL not in repr(value) + assert SENTINEL not in repr(getattr(value, "args", ())) info = getattr(value, "request_info", None) if info is not None: assert SENTINEL not in repr(info) From 8d02edee66a9dd6c608607fc9ac833a8f86dc9e6 Mon Sep 17 00:00:00 2001 From: eli Date: Thu, 29 Oct 2026 13:13:47 -0500 Subject: [PATCH 06/17] PER-16680: scrub error bodies labelled JSON that aren't JSON, and aiohttp error text - An error response whose Content-Type says JSON but whose body isn't JSON (a proxy's error page, a truncated body, one that isn't UTF-8) now raises PermitApiError with the scrubbed body as its details, instead of letting a JSONDecodeError or UnicodeDecodeError, which keep the raw body, escape. The body is scrubbed before it is parsed, and the decode error isn't chained. - PermitConnectionError replaces the key in its message itself, so every raise site is covered, including the ones that build it from an aiohttp error's text. - The aiohttp error it carries has the key replaced in its message, the response headers it keeps and its string arguments, not only in the request headers. - Tests: a body labelled JSON that isn't JSON; an aiohttp error whose text echoes the key, for every enforcer call and the REST API; an echoed key after a followed redirect, and in a list of errors and an object key spelled with JSON escapes. Co-Authored-By: Claude Opus 5.5 --- permit/exceptions.py | 74 +++++++++++++++++---- tests/test_fix_logging.py | 136 ++++++++++++++++++++++++++++++++++++-- 2 files changed, 191 insertions(+), 19 deletions(-) diff --git a/permit/exceptions.py b/permit/exceptions.py index 81c4ca80..3ac6f8d1 100644 --- a/permit/exceptions.py +++ b/permit/exceptions.py @@ -1,6 +1,7 @@ import functools +import json as json_module import warnings -from collections.abc import Awaitable, Callable, Coroutine +from collections.abc import Awaitable, Callable, Coroutine, Mapping from http import HTTPStatus from typing import TYPE_CHECKING, Any, TypeVar, cast @@ -54,7 +55,9 @@ class PermitConnectionError(PermitException): # type: ignore[deprecated] # kept """ def __init__(self, message: str, *, error: aiohttp.ClientError | None = None) -> None: - super().__init__(message) + # Every raise site builds its message from response bodies and aiohttp error + # text, so the key is replaced here, once, rather than at each of them. + super().__init__(sdk_logger.scrub(message)) if error is not None: scrub_request_info(error) self.original_error = error @@ -253,15 +256,31 @@ def _scrubbed(value: _JsonT) -> _JsonT: return value +def _scrubbed_headers(headers: Mapping[str, str]) -> CIMultiDictProxy[str]: + return CIMultiDictProxy( + CIMultiDict((name, sdk_logger.scrub(value)) for name, value in headers.items()) + ) + + +def _scrub_error_text(error: BaseException) -> None: + if isinstance(error, aiohttp.ClientResponseError): + error.message = sdk_logger.scrub(error.message) + if error.headers is not None: + error.headers = _scrubbed_headers(error.headers) + error.args = tuple(sdk_logger.scrub(arg) if isinstance(arg, str) else arg for arg in error.args) + + def scrub_request_info(holder: object) -> None: - """Replace every client's API key in the request headers `holder` keeps. + """Replace every client's API key in the request headers and error text `holder` keeps. aiohttp keeps the request's headers, `Authorization` included, on a `ClientResponse` and a `ClientResponseError` (`request_info`, which the error also keeps as `args[0]`), and on the redirect responses in their `history`; their `repr` - prints them. The SDK puts such objects in the exceptions it raises (`original_error`, - `response`, the exception's cause), so it scrubs them first. Anything else is left - as it is. + prints them. An aiohttp error's text may also hold text a server sent: a + `ClientResponseError`'s `message` and the response `headers` it keeps, another + error's string arguments. The SDK puts such objects in the exceptions it raises + (`original_error`, `response`, the exception's cause), so it scrubs them first. A + `ClientResponse`'s own headers and body, and anything else, are left as they are. Args: holder: An aiohttp response or client error. @@ -269,13 +288,15 @@ def scrub_request_info(holder: object) -> None: for redirect in getattr(holder, "history", None) or (): if redirect is not holder: scrub_request_info(redirect) + if isinstance(holder, BaseException): + _scrub_error_text(holder) info = getattr(holder, "request_info", None) if not isinstance(info, aiohttp.RequestInfo): return - headers = CIMultiDict((name, sdk_logger.scrub(value)) for name, value in info.headers.items()) + headers = _scrubbed_headers(info.headers) if headers == info.headers: return - scrubbed = aiohttp.RequestInfo(info.url, info.method, CIMultiDictProxy(headers), info.real_url) + scrubbed = aiohttp.RequestInfo(info.url, info.method, headers, info.real_url) if isinstance(holder, aiohttp.ClientResponse): # `request_info` is a read-only property over `_request_info`, cached once read # (aiohttp's `reify`): replace both. tests/test_fix_logging.py checks the result. @@ -289,6 +310,36 @@ def scrub_request_info(holder: object) -> None: holder.args = tuple(scrubbed if arg is info else arg for arg in holder.args) +def _scrubbed_loads(text: str) -> Any: # noqa: ANN401 - any JSON value + return json_module.loads(sdk_logger.scrub(text)) + + +async def _scrubbed_text(response: aiohttp.ClientResponse) -> str: + """The body of `response` as text, every registered API key replaced.""" + return sdk_logger.scrub(await response.text(errors="replace")) + + +async def _error_json(response: aiohttp.ClientResponse) -> Any: # noqa: ANN401 - any JSON value + """The decoded JSON body of an error response, every registered API key replaced. + + Raises: + PermitApiError: When the body is not JSON, whatever its Content-Type says. + """ + try: + # The body is scrubbed before it is parsed too, so a decode error's `doc` never + # holds the key. + return _scrubbed(await response.json(loads=_scrubbed_loads)) + except aiohttp.ContentTypeError as e: + scrub_request_info(e) + raise PermitApiError(response, {"details": await _scrubbed_text(response)}) from e + except ValueError: + # Labelled JSON but not JSON, such as a proxy's error page or a truncated body. + # A UnicodeDecodeError keeps the raw bytes, so the decode error isn't chained: + # raised after this block, it isn't the new exception's context either. + error = PermitApiError(response, {"details": await _scrubbed_text(response)}) + raise error + + async def handle_api_error(response: aiohttp.ClientResponse) -> None: """Raise the matching SDK exception if `response` has a non-2xx status. @@ -305,12 +356,7 @@ async def handle_api_error(response: aiohttp.ClientResponse) -> None: if HTTPStatus.OK <= response.status < HTTPStatus.MULTIPLE_CHOICES: return - try: - json = _scrubbed(await response.json()) - except aiohttp.ContentTypeError as e: - scrub_request_info(e) - text = sdk_logger.scrub(await response.text()) - raise PermitApiError(response, {"details": text}) from e + json = await _error_json(response) if response.status == HTTPStatus.UNPROCESSABLE_ENTITY: try: diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py index 86d9db2a..73839e57 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -701,22 +701,59 @@ def echo_the_key_as_json(request: Request) -> Response: return Response(json.dumps(body), status=403, content_type="application/json") -@pytest.mark.parametrize("handler", [echo_the_key, echo_the_key_as_json], ids=["text", "json"]) +def json_escaped(text: str) -> str: + r"""`text` as JSON may spell it in a string: every character a `\u` escape. + + The key then appears only once the body is decoded, not in its raw text. + """ + return "".join(f"\\u{ord(char):04x}" for char in text) + + +def echo_the_key_in_a_list(request: Request) -> Response: + """An API that rejects the request and echoes the key it was sent, in a list of errors.""" + key = json_escaped(request.headers["Authorization"]) + body = f'{{"detail": [{{"msg": "bad key {key}"}}]}}' + return Response(body, status=422, content_type="application/json") + + +def redirect_to_user_2(_: Request) -> Response: + """A redirect the client follows, with its headers, to the user-2 URL.""" + return Response(status=307, headers={"Location": f"{USERS}/user-2"}) + + +@pytest.mark.parametrize( + "handler", + [echo_the_key, echo_the_key_as_json, echo_the_key_in_a_list], + ids=["text", "json", "json-list"], +) async def test_api_and_pdp_api_errors_do_not_hold_an_echoed_key( httpserver: HTTPServer, handler: Callable[[Request], Response] ) -> None: """The REST API and the PDP's local API raise through `handle_api_error`.""" serve(httpserver) httpserver.expect_request(f"{USERS}/user-2", method="GET").respond_with_handler(handler) + httpserver.expect_request(f"{USERS}/moved", method="GET").respond_with_handler( + redirect_to_user_2 + ) httpserver.expect_request("/local/role_assignments", method="GET").respond_with_handler(handler) permit = Permit(make_config(httpserver)) raised: list[BaseException] = [] - for call in (permit.api.users.get("user-2"), permit.pdp_api.role_assignments.list()): + for call in ( + permit.api.users.get("user-2"), + permit.api.users.get("moved"), + permit.pdp_api.role_assignments.list(), + ): with pytest.raises((PermitApiError, PermitConnectionError)) as caught: await call raised.append(caught.value) + # The redirect was followed, with the key: the redirect response keeps the request + # headers it was sent with. + [redirected] = [ + error for error in raised if isinstance(error, PermitApiError) and error.response.history + ] + assert redirected.response.history[0].status == 307 for error in raised: assert SENTINEL not in str(error) assert SENTINEL not in repr(error) @@ -727,14 +764,19 @@ async def test_api_and_pdp_api_errors_do_not_hold_an_echoed_key( def assert_holds_no_key(error: BaseException) -> None: """Assert neither `error` nor the aiohttp objects it carries print the key. - Those are its cause and context, `original_error`, and a `PermitApiError`'s response. + Those are its cause and context, `original_error`, a `PermitApiError`'s response and + details, and the redirect responses in the `history` of any of them. """ + assert SENTINEL not in str(error) + assert SENTINEL not in repr(error.args) + assert SENTINEL not in repr(getattr(error, "details", None)) carried = [ error.__cause__, error.__context__, getattr(error, "original_error", None), getattr(error, "_response", None), ] + carried += [redirect for value in carried for redirect in getattr(value, "history", None) or ()] for value in carried: assert SENTINEL not in repr(value) assert SENTINEL not in repr(getattr(value, "args", ())) @@ -850,8 +892,9 @@ def test_an_unknown_level_is_warned_about_once(httpserver: HTTPServer, app_sinks def echo_the_key_as_a_json_object_key(request: Request) -> Response: """An API that rejects the request and puts the key it was sent in an object key.""" - body = {"detail": {request.headers["Authorization"]: "rejected"}, "error_code": "x"} - return Response(json.dumps(body), status=403, content_type="application/json") + key = json_escaped(request.headers["Authorization"]) + body = f'{{"detail": {{"{key}": "rejected"}}, "error_code": "x"}}' + return Response(body, status=403, content_type="application/json") async def test_an_echoed_key_in_a_json_object_key_is_redacted(httpserver: HTTPServer) -> None: @@ -877,3 +920,86 @@ def test_a_key_in_the_label_is_redacted(httpserver: HTTPServer, app_sinks: AppSi assert records for record in records: assert SENTINEL not in record["message"] + + +@pytest.mark.parametrize( + "body", + [ + pytest.param(lambda auth: f"rejected key {auth}".encode(), id="html"), + pytest.param(lambda auth: f'{{"detail": "rejected key {auth}"'.encode(), id="truncated"), + pytest.param(lambda auth: b"\xff rejected key " + auth.encode(), id="not-utf-8"), + ], +) +async def test_an_error_body_labelled_json_that_is_not_json_raises_a_permit_api_error( + httpserver: HTTPServer, body: Callable[[str], bytes] +) -> None: + serve(httpserver) + + def handler(request: Request) -> Response: + return Response( + body(request.headers["Authorization"]), + status=502, + content_type="application/json; charset=utf-8", + ) + + httpserver.expect_request(f"{USERS}/user-6", method="GET").respond_with_handler(handler) + permit = Permit(make_config(httpserver)) + + with pytest.raises(PermitApiError) as caught: + await permit.api.users.get("user-6") + + assert caught.value.status_code == 502 + assert caught.value.details is not None + assert f"rejected key Bearer {REDACTED}" in caught.value.details["details"] + assert_holds_no_key(caught.value) + + +# aiohttp lower-cases the Content-Type it puts in the message of the error it raises for +# an answer that isn't JSON, so this key is lower case: the SDK replaces a key as given. +LOWER_CASE_KEY = SENTINEL.lower() + + +def answer_with_the_key_in_the_content_type(request: Request) -> Response: + """A 200 answer that isn't JSON, its Content-Type echoing the key the request carried.""" + key = request.headers["Authorization"].removeprefix("Bearer ") + return Response("not json", status=200, content_type=f"text/html; echo={key}") + + +async def test_a_connection_error_holds_no_key_from_the_aiohttp_error_text( + httpserver: HTTPServer, +) -> None: + """The text of an aiohttp error goes into the message of the PermitConnectionError.""" + for path in ("/allowed", "/allowed/bulk", "/authorized_users", "/user-permissions"): + httpserver.expect_request(path, method="POST").respond_with_handler( + answer_with_the_key_in_the_content_type + ) + httpserver.expect_request(f"{USERS}/user-7", method="GET").respond_with_handler( + answer_with_the_key_in_the_content_type + ) + # After the handlers above: the first one registered for a request answers it. + serve(httpserver) + permit = Permit(make_config(httpserver, token=LOWER_CASE_KEY)) + sync_permit = SyncPermit(make_config(httpserver, token=LOWER_CASE_KEY)) + + calls: list[Callable[[], Any]] = [ + lambda: permit.check("user-1", "read", "document"), + lambda: permit.bulk_check(BULK), + lambda: permit.authorized_users("read", "document"), + lambda: permit.get_user_permissions("user-1"), + lambda: permit.api.users.get("user-7"), + ] + raised: list[PermitConnectionError] = [] + for call in calls: + with pytest.raises(PermitConnectionError) as caught: + await call() + raised.append(caught.value) + with pytest.raises(PermitConnectionError) as caught: + sync_permit.check("user-1", "read", "document") + raised.append(caught.value) + + for error in raised: + # The aiohttp error's text is in the message, the key replaced. + assert f"echo={REDACTED}" in str(error) + for value in (error, error.__cause__, error.original_error): + assert LOWER_CASE_KEY not in str(value) + assert LOWER_CASE_KEY not in repr(value) From b5de9d14c08b1c5125d5602e153b74bc1f9da58d Mon Sep 17 00:00:00 2001 From: eli Date: Thu, 29 Oct 2026 13:13:47 -0500 Subject: [PATCH 07/17] PER-16680: build the clients in the constructors again, without a _connect hook Permit.__init__ called self._connect(), a new override point: an application subclass with its own _connect method had it called by the SDK's constructor. The logging change doesn't need it, so the base constructor builds the four clients again and the blocking client's constructor builds its own after it, as before. A test checks that a subclass's own _connect is left alone. Co-Authored-By: Claude Opus 5.5 --- permit/permit.py | 12 ++++-------- permit/sync.py | 4 +++- tests/test_fix_logging.py | 18 ++++++++++++++++++ 3 files changed, 25 insertions(+), 9 deletions(-) diff --git a/permit/permit.py b/permit/permit.py index 7c403ed3..5524065f 100644 --- a/permit/permit.py +++ b/permit/permit.py @@ -34,18 +34,14 @@ def __init__(self, config: PermitConfig | None = None, **options: Any) -> None: self._config: PermitConfig = config if config is not None else PermitConfig(**options) configure_logger(self._config) - self._connect() - sdk_logger.debug( - f"Permit SDK initialized: api_url={without_userinfo(self._config.api_url)}, " - f"pdp={without_userinfo(self._config.pdp)}" - ) - - def _connect(self) -> None: - """Create the clients that send this client's requests, from its config.""" self._enforcer = Enforcer(self._config) self._api = PermitApiClient(self._config) self._elements = ElementsApi(self._config) self._pdp_api = PermitPdpApiClient(self._config) + sdk_logger.debug( + f"Permit SDK initialized: api_url={without_userinfo(self._config.api_url)}, " + f"pdp={without_userinfo(self._config.pdp)}" + ) @property def config(self) -> PermitConfig: diff --git a/permit/sync.py b/permit/sync.py index 7c197e93..c2e066ad 100644 --- a/permit/sync.py +++ b/permit/sync.py @@ -2,6 +2,7 @@ from permit.api.elements import SyncElementsApi from permit.api.sync_api_client import SyncPermitApiClient +from permit.config import PermitConfig from permit.enforcement.enforcer import ( Action, CheckQuery, @@ -28,7 +29,8 @@ class Permit(AsyncPermit): is not given. """ - def _connect(self) -> None: + def __init__(self, config: PermitConfig | None = None, **options: Any) -> None: + super().__init__(config, **options) self._enforcer = SyncEnforcer(self._config) # type: ignore[assignment] self._api = SyncPermitApiClient(self._config) # type: ignore[assignment] self._elements = SyncElementsApi(self._config) # type: ignore[assignment] diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py index 73839e57..feed9e26 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -1003,3 +1003,21 @@ async def test_a_connection_error_holds_no_key_from_the_aiohttp_error_text( for value in (error, error.__cause__, error.original_error): assert LOWER_CASE_KEY not in str(value) assert LOWER_CASE_KEY not in repr(value) + + +@pytest.mark.parametrize( + "client_class", [pytest.param(Permit, id="async"), pytest.param(SyncPermit, id="sync")] +) +def test_a_subclass_s_own_connect_method_is_not_called_by_the_sdk( + httpserver: HTTPServer, client_class: type[Permit] +) -> None: + """The SDK's constructor calls no method an application's subclass may define.""" + + class AppPermit(client_class): # type: ignore[valid-type,misc] + def _connect(self, url: str) -> str: + return url + + permit = AppPermit(make_config(httpserver)) + + assert permit.api is not None + assert permit._connect("x") == "x" From a8bf8c266b636a5b6b303a3bf6de250097240992 Mon Sep 17 00:00:00 2001 From: eli Date: Thu, 29 Oct 2026 13:16:48 -0500 Subject: [PATCH 08/17] PER-16680: build and scrub a log record only when a sink will receive it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - SdkLogger logs with loguru's lazy option, so the label, the key replacement and the message itself are built only for a record loguru passes on. With the SDK's logging off (the default) a debug record is dropped without being built or scrubbed. An application that turns the permit records on itself still gets them in full. - The enforcer's debug lines, which pformat the request and the response, pass a function that builds the message, so the pformat runs only for a record a sink receives. - A log level such as "Β²", which str.isdigit accepts but int() doesn't, is now an unknown level that falls back to INFO with a warning, instead of failing client creation. - Tests: the echoed-key test runs on both clients, at trace, debug, info, error and critical, with logging off and with the application turning it on; the level sweep runs on both clients, checks the key and that no level falls back to INFO, and covers "fatal"; tests for the 12-character boundary, the label on the unknown-level path, an enabled client undoing the SDK's own disable only once, and a disable the application made for an SDK module before. The fixture resets the set of level names already warned about. Co-Authored-By: Claude Opus 5.5 --- permit/enforcement/enforcer.py | 38 +++++--- permit/logger.py | 5 +- permit/utils/sdk_logger.py | 38 +++++--- tests/test_fix_logging.py | 172 +++++++++++++++++++++++++++++---- 4 files changed, 206 insertions(+), 47 deletions(-) diff --git a/permit/enforcement/enforcer.py b/permit/enforcement/enforcer.py index 01a5fb59..3621f99d 100644 --- a/permit/enforcement/enforcer.py +++ b/permit/enforcement/enforcer.py @@ -209,10 +209,12 @@ async def authorized_users( content: dict[str, Any] = await response.json() sdk_logger.debug( - f"permit.authorized_users() response:" - f"\ninput: {pformat(request_body, indent=2)}" - f"\nresponse status: {response.status}" - f"\nresponse data: {pformat(content, indent=2)}" + lambda: ( + f"permit.authorized_users() response:" + f"\ninput: {pformat(request_body, indent=2)}" + f"\nresponse status: {response.status}" + f"\nresponse data: {pformat(content, indent=2)}" + ) ) result: AuthorizedUsersResult = parse_obj_as(AuthorizedUsersResult, content) return result @@ -328,10 +330,12 @@ async def bulk_check( raise PermitConnectionError(msg) content: dict[str, Any] = await response.json() sdk_logger.debug( - f"permit.check() response:\n" - f"input: {pformat(request_body, indent=2)}\n" - f"response status: {response.status}\n" - f"response data: {pformat(content, indent=2)}" + lambda: ( + f"permit.check() response:\n" + f"input: {pformat(request_body, indent=2)}\n" + f"response status: {response.status}\n" + f"response data: {pformat(content, indent=2)}" + ) ) data = content.get("allow", content.get("result", {}).get("allow", [])) decisions: list[bool] = [bool(item.get("allow", False)) for item in data] @@ -447,10 +451,12 @@ async def check( content: dict[str, Any] = await response.json() sdk_logger.debug( - f"permit.check() response:\n" - f"body: {pformat(body, indent=2)}\n" - f"response status: {response.status}\n" - f"response data: {pformat(content, indent=2)}" + lambda: ( + f"permit.check() response:\n" + f"body: {pformat(body, indent=2)}\n" + f"response status: {response.status}\n" + f"response data: {pformat(content, indent=2)}" + ) ) decision: bool = bool(content.get("allow", False)) return decision @@ -525,9 +531,11 @@ async def get_user_permissions( ) sdk_logger.debug( - f"permit.get_user_permissions() response:\n" - f"input: {pformat(input_data, indent=2)}\n" - f"response data: {pformat(permissions, indent=2)}" + lambda: ( + f"permit.get_user_permissions() response:\n" + f"input: {pformat(input_data, indent=2)}\n" + f"response data: {pformat(permissions, indent=2)}" + ) ) return permissions diff --git a/permit/logger.py b/permit/logger.py index e1bd732b..5c998fdc 100644 --- a/permit/logger.py +++ b/permit/logger.py @@ -80,8 +80,9 @@ def configure_logger(config: PermitConfig) -> None: def _level_no(level: str) -> int | None: level = level.strip() - # A severity number, as loguru accepts it (pydantic turns `10` into "10"). - if level.isdigit(): + # A severity number, as loguru accepts it (pydantic turns `10` into "10"). isdecimal, + # not isdigit: it is true for exactly the digits int() reads, and "Β²" is not one. + if level.isdecimal(): return int(level) upper = level.upper() # loguru's level names are case-sensitive: try the name as given first, so a level the diff --git a/permit/utils/sdk_logger.py b/permit/utils/sdk_logger.py index 8a38f141..cb011ad3 100644 --- a/permit/utils/sdk_logger.py +++ b/permit/utils/sdk_logger.py @@ -1,4 +1,6 @@ import threading +from collections.abc import Callable +from typing import TypeAlias from urllib.parse import urlsplit, urlunsplit from loguru import logger @@ -10,6 +12,10 @@ # The package whose records loguru's logger.enable() and logger.disable() switch on and off. PACKAGE = "permit" +# A message, or a function that builds it, for a message costly to build: it is called +# only for a record that some sink will receive. +Message: TypeAlias = str | Callable[[], str] + class SdkLogger: """Logs the SDK's own records to loguru's logger, applying the SDK's `log` settings. @@ -17,8 +23,9 @@ class SdkLogger: Each record reaches loguru from the SDK module that logged it, so `logger.disable("permit")`, `logger.enable("permit")` and the application's sinks treat it as a record of that module. On the way, this drops records below the minimum - severity, replaces every registered API key with `[REDACTED]` and prefixes the message - with the label. + severity. For a record loguru passes on, the message is then built, prefixed with the + label and has every registered API key replaced with `[REDACTED]`; for one it drops, + while the package is disabled or below every sink's level, none of that is done. Its settings are process-wide, like loguru's logger. Until `enable` is called, it keeps every record and adds no label. @@ -96,29 +103,34 @@ def scrub(self, text: str) -> str: text = text.replace(secret, REDACTED) return text - def debug(self, message: str) -> None: + def debug(self, message: Message) -> None: """Log `message` with severity DEBUG.""" self._log("DEBUG", message) - def warning(self, message: str) -> None: + def warning(self, message: Message) -> None: """Log `message` with severity WARNING.""" self._log("WARNING", message) - def error(self, message: str) -> None: + def error(self, message: Message) -> None: """Log `message` with severity ERROR.""" self._log("ERROR", message) - def _log(self, level: str, message: str) -> None: + def _log(self, level: str, message: Message) -> None: if logger.level(level).no < self._min_level_no: return - if self._label: - message = f"[{self._label}] {message}" - # After the label goes on, so a key in the label is replaced too. - message = self.scrub(message) + label = self._label # depth=2 skips this method and the one that called it, so loguru attributes the - # record to the SDK module that logged it. The message goes without arguments, so - # loguru does not call str.format on it and braces in it are kept as they are. - logger.opt(depth=2).log(level, message) + # record to the SDK module that logged it. lazy=True: loguru calls the function + # only once its enabled and level checks pass, so a record it drops is never built + # or scrubbed. The message is the argument of "{}", so braces in it are kept. + logger.opt(depth=2, lazy=True).log(level, "{}", lambda: self._render(message, label)) + + def _render(self, message: Message, label: str) -> str: + text = message() if callable(message) else message + if label: + text = f"[{label}] {text}" + # After the label goes on, so a key in the label is replaced too. + return self.scrub(text) def without_userinfo(url: str) -> str: diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py index feed9e26..56cd1d85 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -6,7 +6,9 @@ served by a local pytest_httpserver. """ +import inspect import json +import pprint import re import subprocess import sys @@ -21,6 +23,7 @@ from pytest_httpserver import HTTPServer from werkzeug import Request, Response +import permit.logger as permit_logger from permit import Permit, PermitConfig from permit.enforcement.enforcer import CheckQuery from permit.exceptions import PermitApiError, PermitConnectionError @@ -58,12 +61,13 @@ def _permit_records_enabled() -> bool: @pytest.fixture(autouse=True) -def isolated_logging() -> Iterator[None]: +def isolated_logging(monkeypatch: pytest.MonkeyPatch) -> Iterator[None]: """Start as a fresh process does, and put the SdkLogger and loguru's switches back after. Restoring loguru's switch for "permit" also drops any switch a test set for a module of the package. """ + monkeypatch.setattr(permit_logger, "_warned_levels", set()) was_enabled = _permit_records_enabled() saved = vars(sdk_logger).copy() vars(sdk_logger).update(vars(SdkLogger())) @@ -181,6 +185,22 @@ def use_sync_client(permit: SyncPermit) -> None: permit.bulk_check(BULK) +async def use_client(permit: Permit) -> None: + """`use_async_client` or `use_sync_client`, whichever fits the client.""" + if isinstance(permit, SyncPermit): + use_sync_client(permit) + else: + await use_async_client(permit) + + +async def resolved(result: object) -> object: + """The value of an SDK call: awaited for the async client, as is for the blocking one.""" + return await result if inspect.isawaitable(result) else result + + +CLIENT_CLASSES = [pytest.param(Permit, id="async"), pytest.param(SyncPermit, id="sync")] + + def assert_api_key_not_logged( httpserver: HTTPServer, app_sinks: AppSinks, expected_levels: set[str] ) -> None: @@ -243,23 +263,43 @@ def echo_the_key(request: Request) -> Response: return Response(f"rejected key: {request.headers['Authorization']}", status=403) -@pytest.mark.parametrize("enabled_by", ["config", "application"]) +@pytest.mark.parametrize("client_class", CLIENT_CLASSES) +@pytest.mark.parametrize( + ("log", "application_enables", "logs_the_error"), + [ + pytest.param({"enable": True, "level": "trace"}, False, True, id="trace"), + pytest.param({"enable": True, "level": "debug"}, False, True, id="debug"), + pytest.param({"enable": True, "level": "info"}, False, True, id="info"), + pytest.param({"enable": True, "level": "error"}, False, True, id="error"), + pytest.param({"enable": True, "level": "critical"}, False, False, id="critical"), + pytest.param({"enable": False}, False, False, id="disabled"), + # A client created with logging disabled, whose records the application turns on. + pytest.param({"enable": False}, True, True, id="disabled-application-enables"), + ], +) async def test_an_api_key_the_pdp_echoes_back_is_redacted( - httpserver: HTTPServer, app_sinks: AppSinks, enabled_by: str + httpserver: HTTPServer, + app_sinks: AppSinks, + client_class: type[Permit], + log: dict[str, Any], + *, + application_enables: bool, + logs_the_error: bool, ) -> None: httpserver.expect_request("/allowed", method="POST").respond_with_handler(echo_the_key) - if enabled_by == "config": - permit = Permit(make_config(httpserver, enable=True)) - else: - # A client created with logging disabled, whose records the application turns on. - permit = Permit(make_config(httpserver)) + permit = client_class(make_config(httpserver, **log)) + if application_enables: logger.enable("permit") with pytest.raises(PermitConnectionError) as raised: - await permit.check("user-1", "read", "document") + await resolved(permit.check("user-1", "read", "document")) - [record] = [record for record in app_sinks.sdk_records() if record["level"]["name"] == "ERROR"] - assert f"rejected key: Bearer {REDACTED}" in record["message"] + errors = [record for record in app_sinks.sdk_records() if record["level"]["name"] == "ERROR"] + if logs_the_error: + [record] = errors + assert f"rejected key: Bearer {REDACTED}" in record["message"] + else: + assert app_sinks.sdk_records() == [] assert SENTINEL not in app_sinks.everything() # The application gets the body too, in the exception it may log or report. assert f"rejected key: Bearer {REDACTED}" in str(raised.value) @@ -334,38 +374,51 @@ async def test_a_key_with_a_trailing_space_is_redacted_when_echoed_without_it( pytest.param({"level": "warn"}, {"WARNING", "ERROR"}, id="warn"), pytest.param({"level": "error"}, {"ERROR"}, id="error"), pytest.param({"level": "critical"}, set(), id="critical"), + pytest.param({"level": "fatal"}, set(), id="fatal"), ], ) +@pytest.mark.parametrize("client_class", CLIENT_CLASSES) async def test_level_drops_the_sdk_records_below_it( - httpserver: HTTPServer, app_sinks: AppSinks, log: dict[str, str], expected_levels: set[str] + httpserver: HTTPServer, + app_sinks: AppSinks, + client_class: type[Permit], + log: dict[str, str], + expected_levels: set[str], ) -> None: serve(httpserver) - await use_async_client(Permit(make_config(httpserver, enable=True, **log))) + await use_client(client_class(make_config(httpserver, enable=True, **log))) logger.debug("an application record") assert app_sinks.sdk_levels() == expected_levels + # Each name is one loguru knows, or reads as one: none falls back to INFO. + assert [r for r in app_sinks.sdk_records() if "Unknown log level" in r["message"]] == [] + assert SENTINEL not in app_sinks.everything() # The application's own records are not the SDK's to filter. assert "an application record" in [record["message"] for record in app_sinks.records()] +# "Β²" is a digit to str.isdigit, but not a number int() reads. +@pytest.mark.parametrize("level", ["verbose", "Β²"]) async def test_an_unknown_level_warns_and_logs_at_info( - httpserver: HTTPServer, app_sinks: AppSinks + httpserver: HTTPServer, app_sinks: AppSinks, level: str ) -> None: serve(httpserver) - await use_async_client(Permit(make_config(httpserver, enable=True, level="verbose"))) + await use_async_client(Permit(make_config(httpserver, enable=True, level=level))) warnings = [ record for record in app_sinks.sdk_records() if record["level"]["name"] == "WARNING" - and "Unknown log level 'verbose'" in record["message"] + and f"Unknown log level {level!r}" in record["message"] ] assert len(warnings) == 1 assert "logs at INFO" in warnings[0]["message"] # The same records as with level "info": no DEBUG ones. assert app_sinks.sdk_levels() == {"WARNING", "ERROR"} + # The label applies on this path too. + assert [r for r in app_sinks.sdk_records() if not r["message"].startswith("[Permit] ")] == [] def test_the_traceback_of_a_failed_client_creation_hides_the_api_key( @@ -868,6 +921,14 @@ def test_a_short_token_is_not_redacted_from_the_sdk_s_text() -> None: assert redactor.scrub("bad token for permit.check()") == "bad token for permit.check()" +def test_a_key_of_12_characters_is_redacted_and_one_of_11_is_not() -> None: + redactor = SdkLogger() + redactor.redact("a" * 11) + redactor.redact("b" * 12) + + assert redactor.scrub(f"{'a' * 11} {'b' * 12}") == f"{'a' * 11} {REDACTED}" + + @pytest.mark.parametrize("level", ["10", " debug ", "DEBUG"]) def test_a_numeric_or_padded_level_is_read( httpserver: HTTPServer, app_sinks: AppSinks, level: str @@ -884,7 +945,9 @@ def test_a_numeric_or_padded_level_is_read( def test_an_unknown_level_is_warned_about_once(httpserver: HTTPServer, app_sinks: AppSinks) -> None: for _ in range(3): - SyncPermit(make_config(httpserver, enable=True, level="verbose-once")) + # The name test_an_unknown_level_warns_and_logs_at_info uses too: each test starts + # with no name warned about. + SyncPermit(make_config(httpserver, enable=True, level="verbose")) warnings = [r for r in app_sinks.sdk_records() if "Unknown log level" in r["message"]] assert len(warnings) == 1 @@ -1021,3 +1084,78 @@ def _connect(self, url: str) -> str: assert permit.api is not None assert permit._connect("x") == "x" + + +def test_an_enabled_client_undoes_only_the_sdk_s_own_disable_once( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + SyncPermit(make_config(httpserver)) + # Undoes the disable the client above made. + SyncPermit(make_config(httpserver, enable=True)) + logger.disable("permit") + + # The SDK's own disable was undone already: this one keeps the application's. + with SyncPermit(make_config(httpserver, enable=True)).wait_for_sync(): + pass + + assert app_sinks.sdk_records() == [] + + +def test_undoing_the_sdk_s_disable_undoes_an_sdk_module_disable_made_before_it( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + """Loguru's `logger.disable("permit")` drops every switch set for a module of it. + + So does `logger.enable("permit")`, which the enabled client calls to undo it. The + README says so. + """ + httpserver.expect_request("/allowed", method="POST").respond_with_json({"allow": True}) + logger.disable("permit.enforcement") + SyncPermit(make_config(httpserver)) + + permit = SyncPermit(make_config(httpserver, enable=True, level="debug")) + assert permit.check("user-1", "read", "document") + + modules = {record["name"] for record in app_sinks.sdk_records()} + assert "permit.enforcement.enforcer" in modules + + +@pytest.mark.parametrize("application_enables", [False, True]) +def test_a_record_loguru_drops_is_not_built_or_scrubbed( + httpserver: HTTPServer, + app_sinks: AppSinks, + monkeypatch: pytest.MonkeyPatch, + *, + application_enables: bool, +) -> None: + """With the SDK's logging off, its debug records cost nothing to drop. + + The application may still turn them on itself, and then gets them in full. + """ + httpserver.expect_request("/allowed", method="POST").respond_with_json({"allow": True}) + calls: list[str] = [] + real_scrub = sdk_logger.scrub + + def pformat(value: object, **kwargs: Any) -> str: + calls.append("pformat") + return pprint.pformat(value, **kwargs) + + def scrub(text: str) -> str: + calls.append("scrub") + return real_scrub(text) + + monkeypatch.setattr("permit.enforcement.enforcer.pformat", pformat) + monkeypatch.setattr(sdk_logger, "scrub", scrub) + client = SyncPermit(make_config(httpserver)) + if application_enables: + logger.enable("permit") + + assert client.check("user-1", "read", "document") + + if application_enables: + [record] = app_sinks.sdk_records() + assert record["message"].startswith("permit.check() response:") + assert calls == ["pformat", "pformat", "scrub"] + else: + assert app_sinks.sdk_records() == [] + assert calls == [] From bce21180a07e980a6ea093ebad6f9471c2eeb363 Mon Sep 17 00:00:00 2001 From: eli Date: Thu, 29 Oct 2026 13:18:58 -0500 Subject: [PATCH 09/17] PER-16680: say exactly what is redacted and what "enable": True undoes; lint and deps - README: list where the key is replaced (log messages, exception messages and error bodies, the aiohttp objects the exceptions carry) and where it isn't (the response's own headers and raw body, frame values in tracebacks), and keep the user-name-and-password sentence to the start-up line. - README and docstrings: undoing the SDK's own disable with logger.enable("permit") also drops every disable set for a permit module, before or since, and overrides an application-wide logger.disable("") for the SDK's records. A test covers both. - The repr=False comment on PermitConfig.token now says what it covers: repr() and str() of the config, not every value a traceback prints. - ruff bans the standard logging module in the package, as it bans loguru's logger. - multidict, imported directly, is a declared dependency, in aiohttp's range. Co-Authored-By: Claude Opus 5.5 --- README.md | 28 +++++++++++++++++++--------- permit/config.py | 16 ++++++++++------ permit/logger.py | 7 +++++-- permit/utils/sdk_logger.py | 6 +++--- pyproject.toml | 9 +++++++-- tests/test_fix_logging.py | 22 +++++++++++++--------- uv.lock | 2 ++ 7 files changed, 59 insertions(+), 31 deletions(-) diff --git a/README.md b/README.md index 0e5aa51a..437bc556 100644 --- a/README.md +++ b/README.md @@ -54,8 +54,11 @@ permit = Permit(token="", log={"enable": True, "level": "debug"}) - `"enable": False` (the default) calls loguru's `logger.disable("permit")`. `"enable": True` undoes that call, with `logger.enable("permit")`, only if an earlier client made it. Otherwise a `logger.disable()` your application made for `permit` or one of its modules - still applies. When it does undo it, it also undoes your application's own - `logger.disable("permit")`, and loguru drops any `permit.*` module disable made since. + still applies. When it does undo it, loguru's `logger.enable("permit")` also undoes your + application's own `logger.disable("permit")`, every `logger.disable()` your application + made for a `permit.*` module, before or since, and, for the SDK's records, an + application-wide `logger.disable("")`. Make those calls after creating the clients if + they must hold. - `level` (default `"info"`) is the lowest severity the SDK logs. Its records below it never reach a sink. Your application's own records are not affected. The SDK logs its HTTP requests and the PDP's responses at `"debug"`. With `"enable": True`, for a level name @@ -68,13 +71,20 @@ permit = Permit(token="", log={"enable": True, "level": "debug"}) decides whether the SDK logs, and the last one created with `"enable": True` decides the level and the label, for every client in the process. `wait_for_sync()` builds a new client of the same class, but keeps the process's log settings as they are. -- The SDK replaces the API key of every client in the process with `[REDACTED]` in the - messages it logs, in the error bodies it puts in the exceptions it raises, and in the - request headers of the aiohttp response or error those exceptions carry - (`original_error`, `response`, the cause), so neither an API or PDP that echoes the key - back nor an error tracker that records exceptions exposes it. A key shorter than 12 - characters is not replaced. The client's start-up line and the PDP error messages show - `api_url` and `pdp` without any user name or password in them. +- The SDK replaces the API key of every client in the process with `[REDACTED]` in: + - the messages it logs; + - the messages of the exceptions it raises, and the error bodies in them + (`PermitApiError.details`); + - the aiohttp response or error those exceptions carry (`original_error`, `response`, + the cause): the request headers they keep, the redirect responses in their + `history`, and an aiohttp error's message, arguments and response headers. + + It does not replace the key elsewhere: not in the headers or raw body of the response + itself (`PermitApiError.response.headers`, `await PermitApiError.response.text()`), and + not in the values a traceback shows for each frame (loguru's `diagnose=True`, error + trackers that record local variables), where the key is in the client's options and its + request headers. A key shorter than 12 characters is not replaced. The client's start-up + line shows `api_url` and `pdp` without any user name or password in them. - `level` also takes a loguru severity number, such as `10` for DEBUG. An unknown name is warned about once per process. diff --git a/permit/config.py b/permit/config.py index 7c95a461..bb48dbd2 100644 --- a/permit/config.py +++ b/permit/config.py @@ -22,9 +22,10 @@ class LoggerConfig(BaseModel): the level and the label, for every client in the process. Whatever these settings, the SDK replaces the API key of every client in the process - with `[REDACTED]` in the messages it logs and in the error bodies it puts in the - exceptions it raises. The client's start-up line logs `api_url` and `pdp` without a user - name or password. + with `[REDACTED]` in the messages it logs, in the messages and error bodies of the + exceptions it raises, and in the aiohttp objects those exceptions carry; the README + lists what it does not cover. The client's start-up line logs `api_url` and `pdp` + without a user name or password. """ enable: bool = Field( @@ -32,7 +33,9 @@ class LoggerConfig(BaseModel): description="Whether the SDK logs. False calls loguru's logger.disable('permit'), so " "nothing is logged. True undoes that call with logger.enable('permit') if an earlier " "client made it, and otherwise leaves loguru's switches alone, so a logger.disable() " - "the application made for 'permit' or one of its modules still applies.", + "the application made for 'permit' or one of its modules still applies. When it does " + "undo it, loguru also drops every logger.disable() set for 'permit' or one of its " + "modules, and overrides an application-wide logger.disable('') for the SDK's records.", ) level: str = Field( default="info", @@ -78,8 +81,9 @@ class PermitConfig(BaseModel): # A positional `...`, not `default=...`: type checkers take any `default=` # keyword as a default, so `PermitConfig()` without a token would pass them. - # repr=False keeps the key out of repr() and str() of the config, and so out of - # tracebacks that print frame values, such as loguru's with diagnose=True. + # repr=False keeps the key out of repr() and str() of the config. Tracebacks that print + # frame values, such as loguru's with diagnose=True, still show it in other values: the + # options a client is created with, and the headers of its HTTP clients. token: str = Field( ..., repr=False, diff --git a/permit/logger.py b/permit/logger.py index 5c998fdc..31bf1c0f 100644 --- a/permit/logger.py +++ b/permit/logger.py @@ -36,7 +36,9 @@ def configure_logger(config: PermitConfig) -> None: - `log.enable` False calls `logger.disable("permit")`, so nothing is logged. True undoes that call with `logger.enable("permit")` if an earlier client made it, and otherwise leaves loguru's switches alone, so a `logger.disable` the application made - for the package or one of its modules still applies. + for the package or one of its modules still applies. Undoing it also drops every + `logger.disable` set for the package or one of its modules, before or since, and + overrides an application-wide `logger.disable("")` for the SDK's records. - `log.level` drops the SDK's records below that severity before they reach any sink. - `log.label` is put in brackets before each message. - `log.log_as_json` is not applied: loguru serializes per sink. For JSON output, the @@ -44,7 +46,8 @@ def configure_logger(config: PermitConfig) -> None: then `logger.add(sys.stderr, serialize=True)`. Whatever the settings, the API key in `config.token` is replaced with `[REDACTED]` in - every message the SDK logs and in the error bodies it puts in the exceptions it raises. + every message the SDK logs, in the messages and error bodies of the exceptions it + raises, and in the aiohttp objects those exceptions carry. `log.level` is a level name, in any case, or a loguru severity number. An unknown one does not fail client creation: the SDK logs a warning that names the value, once per diff --git a/permit/utils/sdk_logger.py b/permit/utils/sdk_logger.py index cb011ad3..0b9980ae 100644 --- a/permit/utils/sdk_logger.py +++ b/permit/utils/sdk_logger.py @@ -56,9 +56,9 @@ def enable(self, *, min_level_no: int, label: str) -> None: """Keep the records from `min_level_no` up, with `label` before each message. If `disable` was called since the last `enable`, this undoes it with - `logger.enable("permit")`. Otherwise it leaves loguru's switches alone: loguru's - enable would also drop every `logger.disable` the application set for a module of - the package, and override an application-wide `logger.disable("")`. + `logger.enable("permit")`, which also drops every `logger.disable` set for a module + of the package and overrides an application-wide `logger.disable("")` for its + records. Otherwise it leaves loguru's switches alone, so those still apply. Args: min_level_no: The loguru severity number below which records are dropped. diff --git a/pyproject.toml b/pyproject.toml index 3ef409a0..8a6a3e13 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -30,6 +30,8 @@ classifiers = [ # .github/scripts/audit-deps.sh scans them with --resolution lowest-direct. dependencies = [ "aiohttp>=3.14.3,<4", + # Imported directly (permit/exceptions.py). aiohttp requires it too, in this range. + "multidict>=4.5,<7", # 0.7.3 is the first loguru release that imports without a DeprecationWarning on # Python 3.14: earlier ones call asyncio.iscoroutinefunction, which 3.16 removes. "loguru>=0.7.3,<1", @@ -243,9 +245,12 @@ convention = "google" ban-relative-imports = "all" [tool.ruff.lint.flake8-tidy-imports.banned-api] -# A record logged straight to loguru would skip the SDK's log level and label, and the -# replacement of the API key with [REDACTED] (PER-16680). +# A record logged straight to loguru, or through the standard logging module, would skip +# the SDK's log level and label, and the replacement of the API key with [REDACTED] +# (PER-16680). The whole logging module is banned: logging.info() and the like log to +# the root logger without a getLogger() call. "loguru.logger".msg = "Log through permit.utils.sdk_logger, which redacts the API key." +"logging".msg = "Log through permit.utils.sdk_logger, which redacts the API key." [tool.ruff.lint.flake8-type-checking] # pydantic evaluates field annotations at runtime, so the imports they use diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py index 56cd1d85..ce39be4b 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -1101,20 +1101,24 @@ def test_an_enabled_client_undoes_only_the_sdk_s_own_disable_once( assert app_sinks.sdk_records() == [] -def test_undoing_the_sdk_s_disable_undoes_an_sdk_module_disable_made_before_it( - httpserver: HTTPServer, app_sinks: AppSinks +@pytest.mark.parametrize("disabled", ["permit.enforcement", ""], ids=["sdk-module", "all"]) +def test_undoing_the_sdk_s_disable_undoes_a_disable_the_application_made_before_it( + httpserver: HTTPServer, app_sinks: AppSinks, disabled: str ) -> None: """Loguru's `logger.disable("permit")` drops every switch set for a module of it. - So does `logger.enable("permit")`, which the enabled client calls to undo it. The - README says so. + So does `logger.enable("permit")`, which the enabled client calls to undo it, and it + overrides an application-wide `logger.disable("")` for the SDK's records. The README + says so. """ httpserver.expect_request("/allowed", method="POST").respond_with_json({"allow": True}) - logger.disable("permit.enforcement") - SyncPermit(make_config(httpserver)) - - permit = SyncPermit(make_config(httpserver, enable=True, level="debug")) - assert permit.check("user-1", "read", "document") + logger.disable(disabled) + try: + SyncPermit(make_config(httpserver)) + permit = SyncPermit(make_config(httpserver, enable=True, level="debug")) + assert permit.check("user-1", "read", "document") + finally: + logger.enable(disabled) modules = {record["name"] for record in app_sinks.sdk_records()} assert "permit.enforcement.enforcer" in modules diff --git a/uv.lock b/uv.lock index 5c853a53..d33995c7 100644 --- a/uv.lock +++ b/uv.lock @@ -1012,6 +1012,7 @@ source = { editable = "." } dependencies = [ { name = "aiohttp" }, { name = "loguru" }, + { name = "multidict" }, { name = "pydantic", version = "1.10.26", source = { registry = "https://pypi.org/simple" }, extra = ["email"], marker = "extra == 'group-6-permit-pydantic-v1'" }, { name = "pydantic", version = "2.13.5", source = { registry = "https://pypi.org/simple" }, extra = ["email"], marker = "extra == 'group-6-permit-pydantic-v2' or extra != 'group-6-permit-pydantic-v1'" }, { name = "typing-extensions" }, @@ -1042,6 +1043,7 @@ pydantic-v2 = [ requires-dist = [ { name = "aiohttp", specifier = ">=3.14.3,<4" }, { name = "loguru", specifier = ">=0.7.3,<1" }, + { name = "multidict", specifier = ">=4.5,<7" }, { name = "pydantic", extras = ["email"], marker = "python_full_version < '3.13'", specifier = ">=1.10.18,!=2.0.*,!=2.1.*,!=2.2.*,!=2.3.*,!=2.4.0,!=2.4.1" }, { name = "pydantic", extras = ["email"], marker = "python_full_version == '3.13.*'", specifier = ">=1.10.18,!=2.0.*,!=2.1.*,!=2.2.*,!=2.3.*,!=2.4.*,!=2.5.*,!=2.6.*,!=2.7.*" }, { name = "pydantic", extras = ["email"], marker = "python_full_version >= '3.14'", specifier = ">=1.10.25,!=2.0.*,!=2.1.*,!=2.2.*,!=2.3.*,!=2.4.*,!=2.5.*,!=2.6.*,!=2.7.*,!=2.8.*,!=2.9.*,!=2.10.*,!=2.11.*,!=2.12.*" }, From e0c373d67187e60f248b3d4410d8efd065dc4936 Mon Sep 17 00:00:00 2001 From: eli Date: Thu, 29 Oct 2026 14:27:33 -0500 Subject: [PATCH 10/17] PER-16680: scrub the errors chained under an aiohttp error, and a lower-cased key - The aiohttp error an SDK exception carries is scrubbed together with every exception chained under it, such as the HTTP parser errors aiohttp raises it from: their string args, message, line, and the URL an InvalidURL error prints. Tested against the whole formatted traceback, for a bad header, a bad status line, a redirect to an invalid URL and one to a non-HTTP URL, on the PDP and the REST API, with both clients. The non-HTTP redirect keeps the key in args only. - Each key is also replaced in lower case: aiohttp lower-cases some server text, such as a Content-Type, in its error messages. The test key is now mixed case. - The enforcer reads a PDP error body with errors="replace", so a body that isn't valid UTF-8 raises PermitConnectionError instead of a UnicodeDecodeError that keeps the raw bytes. - PermitConnectionError keeps a message that isn't a string as it is, as before. - README: say what the redaction covers, now including the chained exceptions, and that URLs and a redirect response's own headers are not covered. Co-Authored-By: Claude Opus 5.5 --- README.md | 25 +++--- permit/enforcement/enforcer.py | 4 +- permit/exceptions.py | 58 +++++++++--- permit/utils/sdk_logger.py | 5 +- tests/test_fix_logging.py | 156 ++++++++++++++++++++++++++++----- 5 files changed, 205 insertions(+), 43 deletions(-) diff --git a/README.md b/README.md index 437bc556..bb03481e 100644 --- a/README.md +++ b/README.md @@ -71,20 +71,25 @@ permit = Permit(token="", log={"enable": True, "level": "debug"}) decides whether the SDK logs, and the last one created with `"enable": True` decides the level and the label, for every client in the process. `wait_for_sync()` builds a new client of the same class, but keeps the process's log settings as they are. -- The SDK replaces the API key of every client in the process with `[REDACTED]` in: +- The SDK replaces the API key of every client in the process, as given and in lower case, + with `[REDACTED]` in: - the messages it logs; - the messages of the exceptions it raises, and the error bodies in them (`PermitApiError.details`); - the aiohttp response or error those exceptions carry (`original_error`, `response`, - the cause): the request headers they keep, the redirect responses in their - `history`, and an aiohttp error's message, arguments and response headers. - - It does not replace the key elsewhere: not in the headers or raw body of the response - itself (`PermitApiError.response.headers`, `await PermitApiError.response.text()`), and - not in the values a traceback shows for each frame (loguru's `diagnose=True`, error - trackers that record local variables), where the key is in the client's options and its - request headers. A key shorter than 12 characters is not replaced. The client's start-up - line shows `api_url` and `pdp` without any user name or password in them. + the cause), and every exception chained under that error: the request headers they + keep, the request headers of the redirect responses in their `history`, and an + error's message, arguments, URL and the response headers it keeps. + + It does not replace the key elsewhere: not in URLs (`PermitApiError.request_url`, the + `url` and `real_url` of a response or its `request_info`, the `url=` part of an aiohttp + error's text), not in the headers or raw body of a response itself + (`PermitApiError.response.headers`, a redirect response's `Location`, + `await PermitApiError.response.text()`), and not in the values a traceback shows for + each frame (loguru's `diagnose=True`, error trackers that record local variables), where + the key is in the client's options and its request headers. A key shorter than 12 + characters is not replaced. The client's start-up line shows `api_url` and `pdp` without + any user name or password in them. - `level` also takes a loguru severity number, such as `10` for DEBUG. An unknown name is warned about once per process. diff --git a/permit/enforcement/enforcer.py b/permit/enforcement/enforcer.py index 3621f99d..0636db3e 100644 --- a/permit/enforcement/enforcer.py +++ b/permit/enforcement/enforcer.py @@ -67,7 +67,9 @@ async def _read_body_text(response: aiohttp.ClientResponse) -> str: except (aiohttp.ClientError, ValueError): pass try: - text = (await response.text()).strip() + # errors="replace": a body that isn't valid in its charset must not escape as a + # UnicodeDecodeError, which isn't a PermitError and keeps the raw, unscrubbed bytes. + text = (await response.text(errors="replace")).strip() except aiohttp.ClientError: return "" return text or "" diff --git a/permit/exceptions.py b/permit/exceptions.py index 3ac6f8d1..4be37adf 100644 --- a/permit/exceptions.py +++ b/permit/exceptions.py @@ -54,10 +54,11 @@ class PermitConnectionError(PermitException): # type: ignore[deprecated] # kept with a changelog entry, not in a dependency-security patch. """ - def __init__(self, message: str, *, error: aiohttp.ClientError | None = None) -> None: + def __init__(self, message: object, *, error: aiohttp.ClientError | None = None) -> None: # Every raise site builds its message from response bodies and aiohttp error - # text, so the key is replaced here, once, rather than at each of them. - super().__init__(sdk_logger.scrub(message)) + # text, so the key is replaced here, once, rather than at each of them. The + # class is public, and a message that isn't a string is kept as it is. + super().__init__(sdk_logger.scrub(message) if isinstance(message, str) else message) if error is not None: scrub_request_info(error) self.original_error = error @@ -262,11 +263,38 @@ def _scrubbed_headers(headers: Mapping[str, str]) -> CIMultiDictProxy[str]: ) +# The attributes, besides `args`, in which aiohttp's errors and the HTTP parser errors +# chained under them keep text a server sent: `message` (ClientResponseError, +# HttpProcessingError), `line` (BadStatusLine), and `_url` and `_description` (InvalidURL +# and its redirect subclasses, whose str() and repr() read `_url`, not `args`). +_TEXT_ATTRIBUTES = ("message", "line", "_url", "_description") + + +def _chain(error: BaseException) -> list[BaseException]: + """`error` and every exception chained under it, as a traceback prints them.""" + chain: list[BaseException] = [] + pending: list[BaseException | None] = [error] + while pending: + current = pending.pop() + if current is None or any(current is seen for seen in chain): + continue + chain.append(current) + pending += [current.__cause__, current.__context__] + return chain + + def _scrub_error_text(error: BaseException) -> None: - if isinstance(error, aiohttp.ClientResponseError): - error.message = sdk_logger.scrub(error.message) - if error.headers is not None: - error.headers = _scrubbed_headers(error.headers) + attributes = getattr(error, "__dict__", {}) + for name in _TEXT_ATTRIBUTES: + value = attributes.get(name) + # `_url` may be a yarl URL: replaced with its scrubbed text only if it holds a key. + if value is None or not (isinstance(value, str) or name == "_url"): + continue + text = str(value) + if sdk_logger.scrub(text) != text: + setattr(error, name, sdk_logger.scrub(text)) + if isinstance(attributes.get("headers"), Mapping): + error.headers = _scrubbed_headers(error.headers) # type: ignore[attr-defined] error.args = tuple(sdk_logger.scrub(arg) if isinstance(arg, str) else arg for arg in error.args) @@ -278,13 +306,23 @@ def scrub_request_info(holder: object) -> None: keeps as `args[0]`), and on the redirect responses in their `history`; their `repr` prints them. An aiohttp error's text may also hold text a server sent: a `ClientResponseError`'s `message` and the response `headers` it keeps, another - error's string arguments. The SDK puts such objects in the exceptions it raises - (`original_error`, `response`, the exception's cause), so it scrubs them first. A - `ClientResponse`'s own headers and body, and anything else, are left as they are. + error's string arguments or URL, and the HTTP parser errors chained under it. The SDK + puts such objects in the exceptions it raises (`original_error`, `response`, the + exception's cause), so it scrubs them, and every exception chained under an error, + first. A `ClientResponse`'s own URL, headers and body, and anything else, are left as + they are. Args: holder: An aiohttp response or client error. """ + if isinstance(holder, BaseException): + for error in _chain(holder): + _scrub_holder(error) + else: + _scrub_holder(holder) + + +def _scrub_holder(holder: object) -> None: for redirect in getattr(holder, "history", None) or (): if redirect is not holder: scrub_request_info(redirect) diff --git a/permit/utils/sdk_logger.py b/permit/utils/sdk_logger.py index 0b9980ae..36393cd6 100644 --- a/permit/utils/sdk_logger.py +++ b/permit/utils/sdk_logger.py @@ -76,7 +76,8 @@ def redact(self, secret: str) -> None: The secret without its leading and trailing whitespace is replaced too: a key read from a file or an environment variable may end with a space, which an HTTP server - that echoes the key back has stripped. + that echoes the key back has stripped. So is each in lower case: aiohttp lower-cases + some of the server text it puts in its error messages, such as a Content-Type. Args: secret: A credential, such as an API key. A secret shorter than @@ -86,7 +87,7 @@ def redact(self, secret: str) -> None: if len(trimmed) < MIN_SECRET_LENGTH: return with self._secrets_lock: - new = {secret, trimmed}.difference(self._secrets) + new = {secret, trimmed, secret.lower(), trimmed.lower()}.difference(self._secrets) if new: self._secrets = tuple(sorted((*self._secrets, *new), key=len, reverse=True)) diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py index ce39be4b..5ea71804 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -10,13 +10,16 @@ import json import pprint import re +import socketserver import subprocess import sys +import threading +import traceback import types from collections.abc import Callable, Iterator from dataclasses import dataclass, field from pathlib import Path -from typing import Any +from typing import Any, cast import pytest from loguru import logger @@ -31,6 +34,8 @@ from permit.utils.sdk_logger import REDACTED, SdkLogger, sdk_logger, without_userinfo SENTINEL = "permit_key_SENTINEL_9f8e7d6c5b4a39281706f5e4d3c2b1a0" +# The key as given and as aiohttp lower-cases it in some of its error messages. +SENTINEL_SPELLINGS = (SENTINEL, SENTINEL.lower()) ORG_ID = "00000000-0000-4000-8000-00000000000a" PROJECT_ID = "00000000-0000-4000-8000-00000000000b" ENV_ID = "00000000-0000-4000-8000-00000000000c" @@ -818,11 +823,16 @@ def assert_holds_no_key(error: BaseException) -> None: """Assert neither `error` nor the aiohttp objects it carries print the key. Those are its cause and context, `original_error`, a `PermitApiError`'s response and - details, and the redirect responses in the `history` of any of them. + details, the redirect responses in the `history` of any of them, and the traceback of + `error` with every exception chained under it. The key is looked for as given and in + lower case. """ - assert SENTINEL not in str(error) - assert SENTINEL not in repr(error.args) - assert SENTINEL not in repr(getattr(error, "details", None)) + shown = [ + str(error), + repr(error.args), + repr(getattr(error, "details", None)), + "".join(traceback.format_exception(error)), + ] carried = [ error.__cause__, error.__context__, @@ -831,12 +841,12 @@ def assert_holds_no_key(error: BaseException) -> None: ] carried += [redirect for value in carried for redirect in getattr(value, "history", None) or ()] for value in carried: - assert SENTINEL not in repr(value) - assert SENTINEL not in repr(getattr(value, "args", ())) + shown += [repr(value), repr(getattr(value, "args", ()))] info = getattr(value, "request_info", None) if info is not None: - assert SENTINEL not in repr(info) - assert SENTINEL not in str(dict(info.headers)) + shown += [repr(info), str(dict(info.headers))] + for key in SENTINEL_SPELLINGS: + assert [text for text in shown if key in text] == [] @pytest.mark.parametrize("status", [200, 502]) @@ -1017,11 +1027,6 @@ def handler(request: Request) -> Response: assert_holds_no_key(caught.value) -# aiohttp lower-cases the Content-Type it puts in the message of the error it raises for -# an answer that isn't JSON, so this key is lower case: the SDK replaces a key as given. -LOWER_CASE_KEY = SENTINEL.lower() - - def answer_with_the_key_in_the_content_type(request: Request) -> Response: """A 200 answer that isn't JSON, its Content-Type echoing the key the request carried.""" key = request.headers["Authorization"].removeprefix("Bearer ") @@ -1031,7 +1036,11 @@ def answer_with_the_key_in_the_content_type(request: Request) -> Response: async def test_a_connection_error_holds_no_key_from_the_aiohttp_error_text( httpserver: HTTPServer, ) -> None: - """The text of an aiohttp error goes into the message of the PermitConnectionError.""" + """The text of an aiohttp error goes into the message of the PermitConnectionError. + + aiohttp lower-cases the Content-Type it puts in the message of the error it raises for + an answer that isn't JSON, so the key, which has capital letters, is there in lower case. + """ for path in ("/allowed", "/allowed/bulk", "/authorized_users", "/user-permissions"): httpserver.expect_request(path, method="POST").respond_with_handler( answer_with_the_key_in_the_content_type @@ -1041,8 +1050,8 @@ async def test_a_connection_error_holds_no_key_from_the_aiohttp_error_text( ) # After the handlers above: the first one registered for a request answers it. serve(httpserver) - permit = Permit(make_config(httpserver, token=LOWER_CASE_KEY)) - sync_permit = SyncPermit(make_config(httpserver, token=LOWER_CASE_KEY)) + permit = Permit(make_config(httpserver)) + sync_permit = SyncPermit(make_config(httpserver)) calls: list[Callable[[], Any]] = [ lambda: permit.check("user-1", "read", "document"), @@ -1063,9 +1072,7 @@ async def test_a_connection_error_holds_no_key_from_the_aiohttp_error_text( for error in raised: # The aiohttp error's text is in the message, the key replaced. assert f"echo={REDACTED}" in str(error) - for value in (error, error.__cause__, error.original_error): - assert LOWER_CASE_KEY not in str(value) - assert LOWER_CASE_KEY not in repr(value) + assert_holds_no_key(error) @pytest.mark.parametrize( @@ -1163,3 +1170,112 @@ def scrub(text: str) -> str: else: assert app_sinks.sdk_records() == [] assert calls == [] + + +@pytest.mark.parametrize("message", [None, 42, b"bytes", ValueError("x")], ids=repr) +def test_a_connection_error_keeps_a_message_that_is_not_a_string( + httpserver: HTTPServer, message: object +) -> None: + Permit(make_config(httpserver)) + + error = PermitConnectionError(message) + + assert error.args == (message,) + + +@pytest.mark.parametrize("client_class", CLIENT_CLASSES) +async def test_a_pdp_error_body_that_is_not_utf_8_raises_a_permit_connection_error( + httpserver: HTTPServer, client_class: type[Permit] +) -> None: + def handler(request: Request) -> Response: + body = b"\xff rejected key: " + request.headers["Authorization"].encode() + return Response(body, status=403, content_type="text/plain; charset=utf-8") + + for path in ("/allowed", "/allowed/bulk", "/authorized_users"): + httpserver.expect_request(path, method="POST").respond_with_handler(handler) + permit = client_class(make_config(httpserver)) + + for call in ( + lambda: permit.check("user-1", "read", "document"), + lambda: permit.bulk_check(BULK), + lambda: permit.authorized_users("read", "document"), + ): + with pytest.raises(PermitConnectionError) as caught: + await resolved(call()) + assert f"rejected key: Bearer {REDACTED}" in str(caught.value) + assert_holds_no_key(caught.value) + + +class _RawHandler(socketserver.StreamRequestHandler): + """Answers a request with the server's raw bytes, then closes the connection.""" + + def handle(self) -> None: + # The request line and headers; any body is left unread. + line = self.rfile.readline() + while line not in (b"\r\n", b"\n", b""): + line = self.rfile.readline() + self.wfile.write(cast("_RawHttpServer", self.server).reply) + + +class _RawHttpServer(socketserver.ThreadingTCPServer): + daemon_threads = True + allow_reuse_address = True + + def __init__(self, reply: bytes) -> None: + super().__init__(("127.0.0.1", 0), _RawHandler) + self.reply = reply + + +EMPTY = "Content-Length: 0\r\n\r\n" + + +def redirect_to(location: str) -> str: + return f"HTTP/1.1 307 TR\r\nLocation: {location}\r\n{EMPTY}" + + +# Answers aiohttp can't use, each holding the key. aiohttp keeps the key in the text of +# the error it raises (its message, its args or its URL), or in the parser error it chains +# under it. +RAW_ANSWERS = [ + pytest.param( + "HTTP/1.1 200 OK\r\nContent-Length: 2\r\nBad Header {key}: x\r\n\r\nok", id="bad-header" + ), + pytest.param("HTTP/1.1 abc {key}\r\n" + EMPTY, id="bad-status-line"), + pytest.param(redirect_to("http://[{key}"), id="invalid-redirect-url"), + pytest.param(redirect_to("ftp://host/{key}"), id="non-http-redirect"), +] + + +@pytest.fixture +def raw_http_server(request: pytest.FixtureRequest) -> Iterator[str]: + """A server that answers with `request.param`, the key put in it; yields its URL.""" + server = _RawHttpServer(request.param.format(key=SENTINEL).encode()) + # A short poll interval: shutdown() waits for the next poll. + thread = threading.Thread(target=server.serve_forever, args=(0.01,), daemon=True) + thread.start() + yield f"http://127.0.0.1:{server.server_address[1]}" + server.shutdown() + server.server_close() + + +@pytest.mark.parametrize("raw_http_server", RAW_ANSWERS, indirect=True) +@pytest.mark.parametrize( + "call", + [ + pytest.param(lambda permit: permit.check("user-1", "read", "document"), id="pdp"), + pytest.param(lambda permit: permit.api.users.get("user-1"), id="api"), + ], +) +@pytest.mark.parametrize("client_class", CLIENT_CLASSES) +async def test_an_aiohttp_error_and_the_errors_chained_under_it_hold_no_key( + raw_http_server: str, client_class: type[Permit], call: Callable[[Permit], object] +) -> None: + permit = client_class( + PermitConfig(token=SENTINEL, api_url=raw_http_server, pdp=raw_http_server) + ) + + with pytest.raises(PermitConnectionError) as caught: + await resolved(call(permit)) + + assert caught.value.original_error is not None + assert_holds_no_key(caught.value) From 8cc038f509507d5d9c9da1c44bcbcdeea171c355 Mon Sep 17 00:00:00 2001 From: eli Date: Thu, 29 Oct 2026 14:27:33 -0500 Subject: [PATCH 11/17] PER-16680: the lazy-record test covers all four enforcer debug lines The test now runs bulk_check, authorized_users and get_user_permissions as well as check, and with the records on asserts that the message was built and scrubbed, without pinning how many pformat calls it makes. Two parametrizations use CLIENT_CLASSES instead of copying it. Co-Authored-By: Claude Opus 5.5 --- tests/test_fix_logging.py | 32 +++++++++++++++++++++++--------- 1 file changed, 23 insertions(+), 9 deletions(-) diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py index 5ea71804..617500a2 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -681,9 +681,7 @@ def test_wait_for_sync_keeps_the_level_and_label_of_the_client_created_last( assert record["message"].startswith(f"[last] {WAIT_FOR_SYNC_WARNING}") -@pytest.mark.parametrize( - "client_class", [pytest.param(Permit, id="async"), pytest.param(SyncPermit, id="sync")] -) +@pytest.mark.parametrize("client_class", CLIENT_CLASSES) async def test_wait_for_sync_yields_a_client_that_waits_for_the_facts( httpserver: HTTPServer, client_class: type[Permit] ) -> None: @@ -1075,9 +1073,7 @@ async def test_a_connection_error_holds_no_key_from_the_aiohttp_error_text( assert_holds_no_key(error) -@pytest.mark.parametrize( - "client_class", [pytest.param(Permit, id="async"), pytest.param(SyncPermit, id="sync")] -) +@pytest.mark.parametrize("client_class", CLIENT_CLASSES) def test_a_subclass_s_own_connect_method_is_not_called_by_the_sdk( httpserver: HTTPServer, client_class: type[Permit] ) -> None: @@ -1131,11 +1127,21 @@ def test_undoing_the_sdk_s_disable_undoes_a_disable_the_application_made_before_ assert "permit.enforcement.enforcer" in modules +LAZY_DEBUG_CALLS: list[Any] = [ + pytest.param(lambda permit: permit.check("user-1", "read", "document"), id="check"), + pytest.param(lambda permit: permit.bulk_check(BULK), id="bulk_check"), + pytest.param(lambda permit: permit.authorized_users("read", "document"), id="authorized_users"), + pytest.param(lambda permit: permit.get_user_permissions("user-1"), id="get_user_permissions"), +] + + +@pytest.mark.parametrize("call", LAZY_DEBUG_CALLS) @pytest.mark.parametrize("application_enables", [False, True]) def test_a_record_loguru_drops_is_not_built_or_scrubbed( httpserver: HTTPServer, app_sinks: AppSinks, monkeypatch: pytest.MonkeyPatch, + call: Callable[[SyncPermit], object], *, application_enables: bool, ) -> None: @@ -1144,6 +1150,13 @@ def test_a_record_loguru_drops_is_not_built_or_scrubbed( The application may still turn them on itself, and then gets them in full. """ httpserver.expect_request("/allowed", method="POST").respond_with_json({"allow": True}) + httpserver.expect_request("/allowed/bulk", method="POST").respond_with_json( + {"allow": [{"allow": True}]} + ) + httpserver.expect_request("/authorized_users", method="POST").respond_with_json( + {"resource": "document:*", "tenant": "default", "users": {}} + ) + httpserver.expect_request("/user-permissions", method="POST").respond_with_json({}) calls: list[str] = [] real_scrub = sdk_logger.scrub @@ -1161,12 +1174,13 @@ def scrub(text: str) -> str: if application_enables: logger.enable("permit") - assert client.check("user-1", "read", "document") + call(client) if application_enables: [record] = app_sinks.sdk_records() - assert record["message"].startswith("permit.check() response:") - assert calls == ["pformat", "pformat", "scrub"] + assert record["level"]["name"] == "DEBUG" + assert "pformat" in calls + assert "scrub" in calls else: assert app_sinks.sdk_records() == [] assert calls == [] From 1eea9d8ba5a3068ffae9b1210c1a5cae422dbcdf Mon Sep 17 00:00:00 2001 From: eli Date: Thu, 29 Oct 2026 14:27:33 -0500 Subject: [PATCH 12/17] PER-16680: note that the floor lanes run multidict 4.5.0 as pure Python The multidict floor stays at aiohttp's own, 4.5, so declaring it narrows nothing users can install. The comment now says that the lowest-direct floor lanes therefore run 4.5.0, which has no C extension build for Python 3.10+. Co-Authored-By: Claude Opus 5.5 --- pyproject.toml | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/pyproject.toml b/pyproject.toml index 8a6a3e13..8c508b20 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -30,7 +30,11 @@ classifiers = [ # .github/scripts/audit-deps.sh scans them with --resolution lowest-direct. dependencies = [ "aiohttp>=3.14.3,<4", - # Imported directly (permit/exceptions.py). aiohttp requires it too, in this range. + # Imported directly (permit/exceptions.py). aiohttp requires it too, in this range, + # so this adds no constraint. The floor is aiohttp's: permit uses only CIMultiDict and + # CIMultiDictProxy, and its tests pass on 4.5.0. So the floor lanes + # (--resolution lowest-direct) run multidict 4.5.0, which has no C extension build for + # Python 3.10+ and runs as pure Python there; the other lanes run the compiled 6.x. "multidict>=4.5,<7", # 0.7.3 is the first loguru release that imports without a DeprecationWarning on # Python 3.14: earlier ones call asyncio.iscoroutinefunction, which 3.16 removes. From 329436039c1585fc03f850d7934328ebf8786ca7 Mon Sep 17 00:00:00 2001 From: eli Date: Thu, 29 Oct 2026 16:18:30 -0500 Subject: [PATCH 13/17] PER-16680: change only what the request raised, and never fail on a scrub The walk over the exceptions chained under a carried aiohttp error reached, through __context__, an exception the application was handling when it called the SDK, and wrote to it. A frozen dataclass exception, read-only args or a headers dict with a value that isn't a string then made the scrub raise inside PermitConnectionError.__init__, so the caller got that error instead of a PermitConnectionError. - The walk keeps only exceptions raised and caught within the request: every frame of their traceback is in aiohttp, the libraries it raises errors from, asyncio or the SDK. It doesn't go past any other exception, so the application's exception and its own chain are never changed. - A value is written only when it holds a key, each write is guarded, and scrub_request_info never raises: it returns False when a value that holds a key can't be replaced. PermitConnectionError then attaches a plain ClientError that says so, and every raise site raises from original_error, so the unscrubbed error is neither attached nor the cause. handle_api_error doesn't chain to it either. - Every string and bytes argument and attribute of those exceptions is scrubbed, not a fixed list, and so is a yarl URL, which becomes a string when it holds a key. - Tests: the application's exception (frozen, headers with an int, read-only args) is left alone and PermitConnectionError is still raised, on both clients, for the PDP and the REST API; a scrub that fails is not attached or the cause, at every raise site; an error chained only as the context; a __cause__ cycle, in a subprocess; raw answers whose errors keep the key as bytes (a header line too long, a NUL in a header) and as a yarl URL; a padded key echoed in lower case. assert_holds_no_key also checks every attribute of every chained exception, and the raw-server test checks that each case still reaches a key to replace. Co-Authored-By: Claude Opus 5.5 --- permit/enforcement/enforcer.py | 21 ++- permit/exceptions.py | 202 ++++++++++++++++++++------- permit/utils/sdk_logger.py | 13 ++ tests/test_fix_logging.py | 244 +++++++++++++++++++++++++++++++-- 4 files changed, 408 insertions(+), 72 deletions(-) diff --git a/permit/enforcement/enforcer.py b/permit/enforcement/enforcer.py index 0636db3e..49feafd0 100644 --- a/permit/enforcement/enforcer.py +++ b/permit/enforcement/enforcer.py @@ -231,10 +231,8 @@ async def authorized_users( f"{self._shown_pdp_url} and accepting requests.\n " f"Read more about setting up the PDP at {SETUP_PDP_DOCS_LINK}" ) - raise PermitConnectionError( - msg, - error=err, - ) from err + error = PermitConnectionError(msg, error=err) + raise error from error.original_error async def bulk_check( self, @@ -356,7 +354,8 @@ async def bulk_check( err, ) sdk_logger.error(msg) - raise PermitConnectionError(msg, error=err) from err + error = PermitConnectionError(msg, error=err) + raise error from error.original_error return decisions async def check( @@ -475,10 +474,8 @@ async def check( f"running at {self._shown_pdp_url} and accepting requests. \n" f"Read more about setting up the PDP at {SETUP_PDP_DOCS_LINK}" ) - raise PermitConnectionError( - msg, - error=err, - ) from err + error = PermitConnectionError(msg, error=err) + raise error from error.original_error async def get_user_permissions( self, @@ -550,10 +547,8 @@ async def get_user_permissions( f"running at {self._shown_pdp_url} and accepting requests. \n" f"Read more about setting up the PDP at {SETUP_PDP_DOCS_LINK}" ) - raise PermitConnectionError( - msg, - error=err, - ) from err + error = PermitConnectionError(msg, error=err) + raise error from error.original_error async def filter_objects( self, user: User, action: Action, context: Context, resources: list[dict[str, Any]] diff --git a/permit/exceptions.py b/permit/exceptions.py index 4be37adf..06cfed23 100644 --- a/permit/exceptions.py +++ b/permit/exceptions.py @@ -59,8 +59,14 @@ def __init__(self, message: object, *, error: aiohttp.ClientError | None = None) # text, so the key is replaced here, once, rather than at each of them. The # class is public, and a message that isn't a string is kept as it is. super().__init__(sdk_logger.scrub(message) if isinstance(message, str) else message) - if error is not None: - scrub_request_info(error) + if error is not None and not scrub_request_info(error): + # Fail closed: an error the key could not be removed from is not attached. + # The SDK raises this exception `from original_error`, so it is not the + # cause either. + error = aiohttp.ClientError( + f"{type(error).__name__}, not attached: the API key could not be " + "removed from it" + ) self.original_error = error @@ -263,89 +269,181 @@ def _scrubbed_headers(headers: Mapping[str, str]) -> CIMultiDictProxy[str]: ) -# The attributes, besides `args`, in which aiohttp's errors and the HTTP parser errors -# chained under them keep text a server sent: `message` (ClientResponseError, -# HttpProcessingError), `line` (BadStatusLine), and `_url` and `_description` (InvalidURL -# and its redirect subclasses, whose str() and repr() read `_url`, not `args`). -_TEXT_ATTRIBUTES = ("message", "line", "_url", "_description") +# The packages whose code an SDK request runs through: aiohttp, the libraries it raises +# errors from, asyncio, and the SDK itself. +_REQUEST_PACKAGES = frozenset( + { + "aiohappyeyeballs", + "aiohttp", + "asyncio", + "concurrent", + "multidict", + "permit", + "propcache", + "selectors", + "socket", + "ssl", + "yarl", + } +) + + +def _raised_in_the_request(error: BaseException) -> bool: + """Whether `error` was raised and caught within the SDK's request. + + That is, whether every frame of its traceback is in one of `_REQUEST_PACKAGES`. An + exception the application raised or caught has a frame of the application's: one it + was handling when it called the SDK, which aiohttp's errors keep as their + `__context__`, or one it built and passed in. The SDK never changes such an exception. + """ + frame = error.__traceback__ + if frame is None: + return False + while frame is not None: + module = frame.tb_frame.f_globals.get("__name__") + if not isinstance(module, str) or module.partition(".")[0] not in _REQUEST_PACKAGES: + return False + frame = frame.tb_next + return True def _chain(error: BaseException) -> list[BaseException]: - """`error` and every exception chained under it, as a traceback prints them.""" + """`error` and the exceptions reachable from it through `__cause__` and `__context__`. + + Only exceptions raised in the request are kept, and the walk does not go past any + other: below the application's exception is the application's own history. + """ chain: list[BaseException] = [] + seen: set[int] = set() pending: list[BaseException | None] = [error] while pending: current = pending.pop() - if current is None or any(current is seen for seen in chain): + if current is None or id(current) in seen: continue - chain.append(current) - pending += [current.__cause__, current.__context__] + seen.add(id(current)) + if _raised_in_the_request(current): + chain.append(current) + pending += [current.__cause__, current.__context__] return chain -def _scrub_error_text(error: BaseException) -> None: - attributes = getattr(error, "__dict__", {}) - for name in _TEXT_ATTRIBUTES: - value = attributes.get(name) - # `_url` may be a yarl URL: replaced with its scrubbed text only if it holds a key. - if value is None or not (isinstance(value, str) or name == "_url"): - continue +def _scrubbed_value(value: object) -> object: + """`value` with every registered key replaced, if it is text that can hold one. + + That is a string, bytes, or a yarl URL, which comes back as a string when it holds a + key. Any other value, such as a parsed HTTP message, comes back as it is, and so does + a value without a key: the very same object. + """ + scrubbed: object = value + if isinstance(value, str): + scrubbed = sdk_logger.scrub(value) + elif isinstance(value, bytes): + scrubbed = sdk_logger.scrub_bytes(value) + elif isinstance(value, bytearray): + scrubbed = bytearray(sdk_logger.scrub_bytes(bytes(value))) + elif type(value).__module__.partition(".")[0] == "yarl": text = str(value) - if sdk_logger.scrub(text) != text: - setattr(error, name, sdk_logger.scrub(text)) - if isinstance(attributes.get("headers"), Mapping): - error.headers = _scrubbed_headers(error.headers) # type: ignore[attr-defined] - error.args = tuple(sdk_logger.scrub(arg) if isinstance(arg, str) else arg for arg in error.args) + scrubbed = sdk_logger.scrub(text) + if scrubbed == text: + return value + return value if scrubbed == value else scrubbed -def scrub_request_info(holder: object) -> None: +def _replace(holder: object, name: str, value: object) -> bool: + """Set `holder.name` to `value`; False, never an exception, if it can't be set.""" + try: + setattr(holder, name, value) + except Exception: # noqa: BLE001 - any failure is reported, never raised + return False + return True + + +def _scrub_error_text(error: BaseException) -> bool: + """Replace the key in the text `error` keeps; False if some of it can't be replaced. + + The text is its arguments and its attributes: a `message`, a `line`, an + `InvalidURL`'s `_url`, and the like. Only values that hold a key are written. + """ + scrubbed = True + for name, value in list(getattr(error, "__dict__", {}).items()): + if name == "headers" and isinstance(value, Mapping): + items = [(key, item, _scrubbed_value(item)) for key, item in value.items()] + if any(new is not item for _, item, new in items): + headers = CIMultiDictProxy(CIMultiDict((key, new) for key, _, new in items)) + scrubbed &= _replace(error, name, headers) + continue + new_value = _scrubbed_value(value) + if new_value is not value: + scrubbed &= _replace(error, name, new_value) + args = tuple(_scrubbed_value(arg) for arg in error.args) + if any(new is not arg for new, arg in zip(args, error.args, strict=True)): + scrubbed &= _replace(error, "args", args) + return scrubbed + + +def scrub_request_info(holder: object) -> bool: """Replace every client's API key in the request headers and error text `holder` keeps. aiohttp keeps the request's headers, `Authorization` included, on a `ClientResponse` and a `ClientResponseError` (`request_info`, which the error also keeps as `args[0]`), and on the redirect responses in their `history`; their `repr` - prints them. An aiohttp error's text may also hold text a server sent: a - `ClientResponseError`'s `message` and the response `headers` it keeps, another - error's string arguments or URL, and the HTTP parser errors chained under it. The SDK - puts such objects in the exceptions it raises (`original_error`, `response`, the - exception's cause), so it scrubs them, and every exception chained under an error, - first. A `ClientResponse`'s own URL, headers and body, and anything else, are left as - they are. + prints them. An aiohttp error's text may also hold text a server sent: its string and + bytes arguments and attributes (a `ClientResponseError`'s `message`, an `InvalidURL`'s + URL), the response `headers` it keeps, and the same in the HTTP parser and URL errors + chained under it. The SDK puts such objects in the exceptions it raises + (`original_error`, `response`, the exception's cause), so it scrubs them first. + + Only what was raised within the request is changed (see `_raised_in_the_request`), + and only values that hold a key. A `ClientResponse`'s own URL, headers and body, and + values that aren't text, such as a parsed HTTP message, are left as they are. Args: holder: An aiohttp response or client error. + + Returns: + False if a value that holds a key could not be replaced; it never raises. """ - if isinstance(holder, BaseException): - for error in _chain(holder): - _scrub_holder(error) - else: - _scrub_holder(holder) + try: + return _scrub_chain(holder) if isinstance(holder, BaseException) else _scrub_holder(holder) + except Exception: # noqa: BLE001 - a scrub that fails is reported, never raised + return False + + +def _scrub_chain(error: BaseException) -> bool: + scrubbed = True + # Every one is scrubbed, even after one that could not be. + for chained in _chain(error): + scrubbed &= _scrub_holder(chained) + return scrubbed -def _scrub_holder(holder: object) -> None: +def _scrub_holder(holder: object) -> bool: + scrubbed = True for redirect in getattr(holder, "history", None) or (): if redirect is not holder: - scrub_request_info(redirect) + scrubbed &= scrub_request_info(redirect) if isinstance(holder, BaseException): - _scrub_error_text(holder) + scrubbed &= _scrub_error_text(holder) info = getattr(holder, "request_info", None) if not isinstance(info, aiohttp.RequestInfo): - return + return scrubbed headers = _scrubbed_headers(info.headers) if headers == info.headers: - return - scrubbed = aiohttp.RequestInfo(info.url, info.method, headers, info.real_url) + return scrubbed + replacement = aiohttp.RequestInfo(info.url, info.method, headers, info.real_url) if isinstance(holder, aiohttp.ClientResponse): # `request_info` is a read-only property over `_request_info`, cached once read # (aiohttp's `reify`): replace both. tests/test_fix_logging.py checks the result. - holder._request_info = scrubbed # noqa: SLF001 + scrubbed &= _replace(holder, "_request_info", replacement) cache = getattr(holder, "_cache", None) if isinstance(cache, dict) and "request_info" in cache: - cache["request_info"] = scrubbed - else: - holder.request_info = scrubbed # type: ignore[attr-defined] - if isinstance(holder, BaseException): - holder.args = tuple(scrubbed if arg is info else arg for arg in holder.args) + cache["request_info"] = replacement + return scrubbed + scrubbed &= _replace(holder, "request_info", replacement) + if isinstance(holder, BaseException): + args = tuple(replacement if arg is info else arg for arg in holder.args) + scrubbed &= _replace(holder, "args", args) + return scrubbed def _scrubbed_loads(text: str) -> Any: # noqa: ANN401 - any JSON value @@ -368,8 +466,9 @@ async def _error_json(response: aiohttp.ClientResponse) -> Any: # noqa: ANN401 # holds the key. return _scrubbed(await response.json(loads=_scrubbed_loads)) except aiohttp.ContentTypeError as e: - scrub_request_info(e) - raise PermitApiError(response, {"details": await _scrubbed_text(response)}) from e + # Not chained to an error the key could not be removed from. + cause = e if scrub_request_info(e) else None + raise PermitApiError(response, {"details": await _scrubbed_text(response)}) from cause except ValueError: # Labelled JSON but not JSON, such as a proxy's error page or a truncated body. # A UnicodeDecodeError keeps the raw bytes, so the decode error isn't chained: @@ -435,6 +534,7 @@ async def wrapped(*args: P.args, **kwargs: P.kwargs) -> R: except aiohttp.ClientError as err: sdk_logger.error(f"got client error while sending an http request:\n{err}") msg = f"{err}" - raise PermitConnectionError(msg, error=err) from err + error = PermitConnectionError(msg, error=err) + raise error from error.original_error return wrapped diff --git a/permit/utils/sdk_logger.py b/permit/utils/sdk_logger.py index 36393cd6..c972c755 100644 --- a/permit/utils/sdk_logger.py +++ b/permit/utils/sdk_logger.py @@ -104,6 +104,19 @@ def scrub(self, text: str) -> str: text = text.replace(secret, REDACTED) return text + def scrub_bytes(self, data: bytes) -> bytes: + """Return `data` with every registered secret, UTF-8 encoded, replaced. + + Args: + data: Bytes a server sent, such as an HTTP line an aiohttp error keeps. + + Returns: + The bytes without any registered secret. + """ + for secret in self._secrets: + data = data.replace(secret.encode(), REDACTED.encode()) + return data + def debug(self, message: Message) -> None: """Log `message` with severity DEBUG.""" self._log("DEBUG", message) diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py index 617500a2..4ac0a04b 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -6,6 +6,7 @@ served by a local pytest_httpserver. """ +import dataclasses import inspect import json import pprint @@ -19,8 +20,9 @@ from collections.abc import Callable, Iterator from dataclasses import dataclass, field from pathlib import Path -from typing import Any, cast +from typing import Any, NoReturn, cast +import aiohttp import pytest from loguru import logger from pytest_httpserver import HTTPServer @@ -29,7 +31,7 @@ import permit.logger as permit_logger from permit import Permit, PermitConfig from permit.enforcement.enforcer import CheckQuery -from permit.exceptions import PermitApiError, PermitConnectionError +from permit.exceptions import PermitApiError, PermitConnectionError, scrub_request_info from permit.sync import Permit as SyncPermit from permit.utils.sdk_logger import REDACTED, SdkLogger, sdk_logger, without_userinfo @@ -843,10 +845,24 @@ def assert_holds_no_key(error: BaseException) -> None: info = getattr(value, "request_info", None) if info is not None: shown += [repr(info), str(dict(info.headers))] + # Every attribute of every chained exception, printed or not. + shown += [repr(vars(chained)) + repr(chained.args) for chained in chained_exceptions(error)] for key in SENTINEL_SPELLINGS: assert [text for text in shown if key in text] == [] +def chained_exceptions(error: BaseException) -> list[BaseException]: + """Every exception reachable from `error` through `__cause__` and `__context__`.""" + found: list[BaseException] = [] + pending: list[BaseException | None] = [error] + while pending: + current = pending.pop() + if current is not None and not any(current is seen for seen in found): + found.append(current) + pending += [current.__cause__, current.__context__] + return found + + @pytest.mark.parametrize("status", [200, 502]) async def test_a_non_json_answer_raises_without_the_key_in_its_request_headers( httpserver: HTTPServer, status: int @@ -1026,13 +1042,18 @@ def handler(request: Request) -> Response: def answer_with_the_key_in_the_content_type(request: Request) -> Response: - """A 200 answer that isn't JSON, its Content-Type echoing the key the request carried.""" - key = request.headers["Authorization"].removeprefix("Bearer ") + """A 200 answer that isn't JSON, its Content-Type echoing the key the request carried. + + The key is echoed without surrounding whitespace. + """ + key = request.headers["Authorization"].removeprefix("Bearer ").strip() return Response("not json", status=200, content_type=f"text/html; echo={key}") +# A key read from a file may end with a space, which the echo drops. +@pytest.mark.parametrize("token", [SENTINEL, f"{SENTINEL} "], ids=["key", "padded-key"]) async def test_a_connection_error_holds_no_key_from_the_aiohttp_error_text( - httpserver: HTTPServer, + httpserver: HTTPServer, token: str ) -> None: """The text of an aiohttp error goes into the message of the PermitConnectionError. @@ -1048,8 +1069,8 @@ async def test_a_connection_error_holds_no_key_from_the_aiohttp_error_text( ) # After the handlers above: the first one registered for a request answers it. serve(httpserver) - permit = Permit(make_config(httpserver)) - sync_permit = SyncPermit(make_config(httpserver)) + permit = Permit(make_config(httpserver, token=token)) + sync_permit = SyncPermit(make_config(httpserver, token=token)) calls: list[Callable[[], Any]] = [ lambda: permit.check("user-1", "read", "document"), @@ -1247,15 +1268,23 @@ def redirect_to(location: str) -> str: return f"HTTP/1.1 307 TR\r\nLocation: {location}\r\n{EMPTY}" +LONG = "a" * 9000 + # Answers aiohttp can't use, each holding the key. aiohttp keeps the key in the text of # the error it raises (its message, its args or its URL), or in the parser error it chains -# under it. +# under it, as a string, as bytes or as a yarl URL. RAW_ANSWERS = [ pytest.param( "HTTP/1.1 200 OK\r\nContent-Length: 2\r\nBad Header {key}: x\r\n\r\nok", id="bad-header" ), pytest.param("HTTP/1.1 abc {key}\r\n" + EMPTY, id="bad-status-line"), + # LineTooLong, which keeps the line as bytes in its args. + pytest.param("HTTP/1.1 200 OK\r\nX-Long: {key}" + LONG + "\r\n" + EMPTY, id="header-too-long"), + # InvalidHeader, which keeps the header as bytes in its args. + pytest.param("HTTP/1.1 200 OK\r\nX-Nul: {key}\x00\r\n" + EMPTY, id="nul-in-header"), pytest.param(redirect_to("http://[{key}"), id="invalid-redirect-url"), + # InvalidUrlRedirectClientError with the URL parsed: a yarl URL in `_url` and `args`. + pytest.param(redirect_to("http:///{key}"), id="redirect-url-without-host"), pytest.param(redirect_to("ftp://host/{key}"), id="non-http-redirect"), ] @@ -1293,3 +1322,202 @@ async def test_an_aiohttp_error_and_the_errors_chained_under_it_hold_no_key( assert caught.value.original_error is not None assert_holds_no_key(caught.value) + # The case still reaches a key to replace. + shown = [ + repr(vars(chained)) + repr(chained.args) for chained in chained_exceptions(caught.value) + ] + assert REDACTED in "".join(shown) + + +# Functions that raise and catch in a module of aiohttp's, as aiohttp's own code does: the +# SDK changes only exceptions raised and caught within its request. +AIOHTTP_DOUBLE_SOURCE = """ +import aiohttp + + +def context_only(key): + try: + try: + raise ValueError(f"inner {key}") + except ValueError: + raise aiohttp.ClientError("outer") + except aiohttp.ClientError as error: + return error + + +def raised(error): + try: + raise error + except BaseException as caught: + return caught +""" +aiohttp_double = types.ModuleType("aiohttp._test_double") +exec(AIOHTTP_DOUBLE_SOURCE, aiohttp_double.__dict__) # noqa: S102 - a fixed test double + + +def test_an_error_chained_only_as_the_context_is_scrubbed(httpserver: HTTPServer) -> None: + Permit(make_config(httpserver)) + error = aiohttp_double.context_only(SENTINEL) + inner = error.__context__ + assert error.__cause__ is None + assert isinstance(inner, ValueError) + + assert scrub_request_info(error) + + assert inner.args == (f"inner {REDACTED}",) + + +# A walk that never ends can't be stopped in a thread, so this runs in its own process. +CAUSE_CYCLE_APP = f""" +import sys +import types + +import aiohttp + +from permit import Permit +from permit.exceptions import scrub_request_info + +double = types.ModuleType("aiohttp._test_double") +exec({AIOHTTP_DOUBLE_SOURCE!r}, double.__dict__) +Permit(token="{SENTINEL}") +first = double.raised(aiohttp.ClientError("first {SENTINEL}")) +second = double.raised(aiohttp.ClientError("second {SENTINEL}")) +first.__cause__ = second +second.__cause__ = first +assert scrub_request_info(first) +print(first.args[0], second.args[0]) +""" + + +def test_a_cause_cycle_is_walked_once(tmp_path: Path) -> None: + app = tmp_path / "app.py" + app.write_text(CAUSE_CYCLE_APP) + + result = subprocess.run( + [sys.executable, str(app)], capture_output=True, text=True, timeout=15, check=False + ) + + assert result.returncode == 0, result.stderr + assert result.stdout.split() == ["first", REDACTED, "second", REDACTED] + + +def test_an_error_whose_text_cannot_be_replaced_is_not_attached(httpserver: HTTPServer) -> None: + class FixedArgsError(aiohttp.ClientError): + @property + def args(self) -> tuple[object, ...]: # type: ignore[override] + return (f"fixed {SENTINEL}",) + + Permit(make_config(httpserver)) + original = aiohttp_double.raised(FixedArgsError()) + + error = PermitConnectionError("the request failed", error=original) + + assert error.original_error is not original + assert SENTINEL not in repr(error.original_error) + assert "could not be removed" in str(error.original_error) + + +def raise_(error: BaseException) -> NoReturn: + raise error + + +@dataclasses.dataclass(frozen=True) +class FrozenAppError(Exception): + """An application's exception that can't be changed.""" + + detail: str + + +class AppHeadersError(Exception): + """An application's exception with a headers dict whose values aren't all strings.""" + + def __init__(self) -> None: + super().__init__(f"the application's own text, with the key {SENTINEL}") + self.headers = {"Retry-After": 120, "X-Echo": SENTINEL} + + +class AppFixedArgsError(Exception): + """An application's exception whose args can't be set.""" + + @property + def args(self) -> tuple[object, ...]: # type: ignore[override] + return (f"fixed {SENTINEL}",) + + +@pytest.mark.parametrize( + "app_error", + [ + pytest.param(lambda: FrozenAppError(f"frozen {SENTINEL}"), id="frozen-dataclass"), + pytest.param(AppHeadersError, id="headers-with-an-int"), + pytest.param(AppFixedArgsError, id="read-only-args"), + ], +) +@pytest.mark.parametrize( + "call", + [ + pytest.param(lambda permit: permit.check("user-1", "read", "document"), id="pdp"), + pytest.param(lambda permit: permit.api.users.get("user-1"), id="api"), + ], +) +@pytest.mark.parametrize("client_class", CLIENT_CLASSES) +@pytest.mark.parametrize( + "raw_http_server", [pytest.param(redirect_to("ftp://host/{key}"), id="redirect")], indirect=True +) +async def test_an_exception_the_application_is_handling_is_left_alone( + raw_http_server: str, + client_class: type[Permit], + call: Callable[[Permit], object], + app_error: Callable[[], Exception], +) -> None: + """An application may call the SDK while it handles an exception of its own. + + aiohttp's error then keeps that exception as its context: here, the error for a + redirect to a URL that isn't HTTP, which aiohttp raises in the caller's task. The SDK + still raises PermitConnectionError, and doesn't change the application's exception, + even where it holds the key. + """ + url = raw_http_server + permit = client_class(PermitConfig(token=SENTINEL, api_url=url, pdp=url)) + handled = app_error() + before = (repr(vars(handled)), repr(handled.args)) + + try: + raise_(handled) + except Exception: + with pytest.raises(PermitConnectionError) as caught: + await resolved(call(permit)) + + # The application's exception is in the chain, unchanged. + assert any(chained is handled for chained in chained_exceptions(caught.value)) + assert (repr(vars(handled)), repr(handled.args)) == before + if isinstance(handled, AppHeadersError): + assert type(handled.headers) is dict + assert caught.value.original_error is not None + assert SENTINEL not in repr(vars(caught.value.original_error)) + + +@pytest.mark.parametrize( + "raw_http_server", [pytest.param(redirect_to("ftp://host/{key}"), id="redirect")], indirect=True +) +@pytest.mark.parametrize( + "call", + [*LAZY_DEBUG_CALLS, pytest.param(lambda permit: permit.api.users.get("user-1"), id="api")], +) +@pytest.mark.parametrize("client_class", CLIENT_CLASSES) +async def test_an_error_that_cannot_be_scrubbed_is_neither_attached_nor_the_cause( + raw_http_server: str, + client_class: type[Permit], + call: Callable[[Permit], object], + monkeypatch: pytest.MonkeyPatch, +) -> None: + monkeypatch.setattr("permit.exceptions.scrub_request_info", lambda _: False) + url = raw_http_server + permit = client_class(PermitConfig(token=SENTINEL, api_url=url, pdp=url)) + + with pytest.raises(PermitConnectionError) as caught: + await resolved(call(permit)) + + replacement = caught.value.original_error + assert "could not be removed" in str(replacement) + assert caught.value.__cause__ is replacement + assert SENTINEL not in "".join(traceback.format_exception(caught.value)) From d2d1f869065981a5ce481bc31ecb844925659ef2 Mon Sep 17 00:00:00 2001 From: eli Date: Thu, 29 Oct 2026 16:18:30 -0500 Subject: [PATCH 14/17] PER-16680: README: what the scrub covers, and that it leaves other exceptions alone The redaction list says which chained exceptions are covered (those aiohttp and its libraries raised during the request), that string and bytes values and an invalid-URL error's URL are, the latter becoming a string, and that values that aren't text, such as a parsed HTTP message, are not. It says the SDK never changes an exception it didn't raise, and what it attaches when the key can't be removed. "Request URLs" now names the URLs that are not covered, so it no longer reads as contradicting the invalid-URL item. Co-Authored-By: Claude Opus 5.5 --- README.md | 24 +++++++++++++++++------- 1 file changed, 17 insertions(+), 7 deletions(-) diff --git a/README.md b/README.md index bb03481e..1b39e01d 100644 --- a/README.md +++ b/README.md @@ -77,15 +77,25 @@ permit = Permit(token="", log={"enable": True, "level": "debug"}) - the messages of the exceptions it raises, and the error bodies in them (`PermitApiError.details`); - the aiohttp response or error those exceptions carry (`original_error`, `response`, - the cause), and every exception chained under that error: the request headers they - keep, the request headers of the redirect responses in their `history`, and an - error's message, arguments, URL and the response headers it keeps. - - It does not replace the key elsewhere: not in URLs (`PermitApiError.request_url`, the + the cause), and the exceptions chained under that error that aiohttp and the + libraries it uses raised during the request: the request headers they keep, the + request headers of the redirect responses in their `history`, and each error's + arguments and attributes that are strings or bytes (such as its message), the + response headers it keeps, and the URL of an invalid-URL error (`InvalidURL.url`, + which then becomes a string). + + The SDK never changes an exception it did not raise during the request, such as one + your application was handling when it called the SDK, which aiohttp keeps in its + error's chain. If the key cannot be removed from the aiohttp error, the SDK attaches a + plain `aiohttp.ClientError` that says so in its place, as `original_error` and as the + cause. + + It does not replace the key elsewhere: not in values that are neither text nor a URL, + such as a parsed HTTP message; not in request URLs (`PermitApiError.request_url`, the `url` and `real_url` of a response or its `request_info`, the `url=` part of an aiohttp - error's text), not in the headers or raw body of a response itself + error's text); not in the headers or raw body of a response itself (`PermitApiError.response.headers`, a redirect response's `Location`, - `await PermitApiError.response.text()`), and not in the values a traceback shows for + `await PermitApiError.response.text()`); and not in the values a traceback shows for each frame (loguru's `diagnose=True`, error trackers that record local variables), where the key is in the client's options and its request headers. A key shorter than 12 characters is not replaced. The client's start-up line shows `api_url` and `pdp` without From a4ae142726a423c1328a76df1d770f76c3221e4d Mon Sep 17 00:00:00 2001 From: eli Date: Fri, 30 Oct 2026 08:38:51 -0500 Subject: [PATCH 15/17] PER-16680: always scrub the caught error; fail closed on a key the scrub can't reach - The error the SDK caught is always scrubbed; the frame check applies only to what is chained under it. - The exception the application was handling when it called the SDK is passed in as `handled` and is left alone, with everything under it. - Any other exception left as it is (raised in a package off the list, or with a frame of the application's), or text the scrub can't rewrite (a UnicodeError's `object`), makes the scrub return False if it still holds a key. - PermitConnectionError and PermitApiError are raised after the `except` block, so an error that wasn't attached isn't their context. - Tests: the caught error with a foreign frame; an idna error in a redirect host; a yarl-raised error; all four PDP calls with the application's exception; a refused connection; the frame-check, fail-closed, bytearray and builtin-field paths; and the raw answers on aiohttp's pure-Python parser. Co-Authored-By: Claude Opus 5.5 --- README.md | 8 +- permit/enforcement/enforcer.py | 32 +++- permit/exceptions.py | 135 +++++++++++---- tests/test_fix_logging.py | 301 ++++++++++++++++++++++++++++++++- 4 files changed, 425 insertions(+), 51 deletions(-) diff --git a/README.md b/README.md index 1b39e01d..445ee0e5 100644 --- a/README.md +++ b/README.md @@ -86,9 +86,11 @@ permit = Permit(token="", log={"enable": True, "level": "debug"}) The SDK never changes an exception it did not raise during the request, such as one your application was handling when it called the SDK, which aiohttp keeps in its - error's chain. If the key cannot be removed from the aiohttp error, the SDK attaches a - plain `aiohttp.ClientError` that says so in its place, as `original_error` and as the - cause. + error's chain. If the key cannot be removed from the aiohttp error or an exception + under it, or is still in one under it that the SDK leaves as it is (other than the one + your application was handling), a `PermitConnectionError` carries a plain + `aiohttp.ClientError` that says so in its place, as `original_error` and as the cause, + and a `PermitApiError` for an error body that isn't JSON has no cause. It does not replace the key elsewhere: not in values that are neither text nor a URL, such as a parsed HTTP message; not in request URLs (`PermitApiError.request_url`, the diff --git a/permit/enforcement/enforcer.py b/permit/enforcement/enforcer.py index 49feafd0..8eeab9fa 100644 --- a/permit/enforcement/enforcer.py +++ b/permit/enforcement/enforcer.py @@ -1,4 +1,5 @@ import json +import sys from http import HTTPStatus from pprint import pformat from typing import TYPE_CHECKING, Any, Union @@ -168,6 +169,7 @@ async def authorized_users( "context": query_context, } + handled = sys.exc_info()[1] # the application's, if any: left as it is async with aiohttp.ClientSession(headers=self._headers, **self._timeout_config) as session: check_url = f"{self._base_url}/authorized_users" try: @@ -231,8 +233,10 @@ async def authorized_users( f"{self._shown_pdp_url} and accepting requests.\n " f"Read more about setting up the PDP at {SETUP_PDP_DOCS_LINK}" ) - error = PermitConnectionError(msg, error=err) - raise error from error.original_error + error = PermitConnectionError(msg, error=err, handled=handled) + # Raised after the `except` block, so `err` isn't its context when it isn't + # attached. + raise error from error.original_error async def bulk_check( self, @@ -303,6 +307,7 @@ async def bulk_check( } ) + handled = sys.exc_info()[1] # the application's, if any: left as it is async with aiohttp.ClientSession(headers=self._headers, **self._timeout_config) as session: check_url = f"{self._base_url}/allowed/bulk" try: @@ -354,9 +359,12 @@ async def bulk_check( err, ) sdk_logger.error(msg) - error = PermitConnectionError(msg, error=err) - raise error from error.original_error - return decisions + error = PermitConnectionError(msg, error=err, handled=handled) + else: + return decisions + # Raised after the `except` block, so `err` isn't its context when it isn't + # attached. + raise error from error.original_error async def check( self, @@ -409,6 +417,7 @@ async def check( "resource": normalized_resource.dict(exclude_unset=True), "context": query_context, } + handled = sys.exc_info()[1] # the application's, if any: left as it is async with aiohttp.ClientSession(headers=self._headers, **self._timeout_config) as session: check_url = f"{self._base_url}/allowed" try: @@ -474,8 +483,10 @@ async def check( f"running at {self._shown_pdp_url} and accepting requests. \n" f"Read more about setting up the PDP at {SETUP_PDP_DOCS_LINK}" ) - error = PermitConnectionError(msg, error=err) - raise error from error.original_error + error = PermitConnectionError(msg, error=err, handled=handled) + # Raised after the `except` block, so `err` isn't its context when it isn't + # attached. + raise error from error.original_error async def get_user_permissions( self, @@ -505,6 +516,7 @@ async def get_user_permissions( "resource_types": resource_types, } + handled = sys.exc_info()[1] # the application's, if any: left as it is async with aiohttp.ClientSession(headers=self._headers, **self._timeout_config) as session: url = f"{self._base_url}/user-permissions" try: @@ -547,8 +559,10 @@ async def get_user_permissions( f"running at {self._shown_pdp_url} and accepting requests. \n" f"Read more about setting up the PDP at {SETUP_PDP_DOCS_LINK}" ) - error = PermitConnectionError(msg, error=err) - raise error from error.original_error + error = PermitConnectionError(msg, error=err, handled=handled) + # Raised after the `except` block, so `err` isn't its context when it isn't + # attached. + raise error from error.original_error async def filter_objects( self, user: User, action: Action, context: Context, resources: list[dict[str, Any]] diff --git a/permit/exceptions.py b/permit/exceptions.py index 06cfed23..9f982f67 100644 --- a/permit/exceptions.py +++ b/permit/exceptions.py @@ -1,5 +1,6 @@ import functools import json as json_module +import sys import warnings from collections.abc import Awaitable, Callable, Coroutine, Mapping from http import HTTPStatus @@ -54,12 +55,20 @@ class PermitConnectionError(PermitException): # type: ignore[deprecated] # kept with a changelog entry, not in a dependency-security patch. """ - def __init__(self, message: object, *, error: aiohttp.ClientError | None = None) -> None: + def __init__( + self, + message: object, + *, + error: aiohttp.ClientError | None = None, + handled: BaseException | None = None, + ) -> None: # Every raise site builds its message from response bodies and aiohttp error # text, so the key is replaced here, once, rather than at each of them. The # class is public, and a message that isn't a string is kept as it is. + # `handled` is the exception the application was handling when it called the + # SDK (see `scrub_request_info`). super().__init__(sdk_logger.scrub(message) if isinstance(message, str) else message) - if error is not None and not scrub_request_info(error): + if error is not None and not scrub_request_info(error, handled=handled): # Fail closed: an error the key could not be removed from is not attached. # The SDK raises this exception `from original_error`, so it is not the # cause either. @@ -98,6 +107,8 @@ def __init__( body: dict[str, Any] | None = None, ) -> None: super().__init__() + # The result isn't needed: on a `ClientResponse` the scrub writes only + # `_request_info` and its cache, a plain attribute and a dict, so it can't fail. scrub_request_info(response) self._response = response self._body = body @@ -292,9 +303,9 @@ def _raised_in_the_request(error: BaseException) -> bool: """Whether `error` was raised and caught within the SDK's request. That is, whether every frame of its traceback is in one of `_REQUEST_PACKAGES`. An - exception the application raised or caught has a frame of the application's: one it - was handling when it called the SDK, which aiohttp's errors keep as their - `__context__`, or one it built and passed in. The SDK never changes such an exception. + exception the application raised or caught has a frame of the application's, so the + SDK doesn't change it. So does an error raised in a library missing from the list, + which `_scrub_chain` then checks for a key instead. """ frame = error.__traceback__ if frame is None: @@ -307,24 +318,65 @@ def _raised_in_the_request(error: BaseException) -> bool: return True -def _chain(error: BaseException) -> list[BaseException]: - """`error` and the exceptions reachable from it through `__cause__` and `__context__`. +def _chained(error: BaseException) -> list[BaseException | None]: + return [error.__cause__, error.__context__] - Only exceptions raised in the request are kept, and the walk does not go past any - other: below the application's exception is the application's own history. + +def _chain( + error: BaseException, handled: BaseException | None +) -> tuple[list[BaseException], list[BaseException]]: + """The exceptions reachable from `error` through `__cause__` and `__context__`. + + Returns them in two lists: those to scrub, which are `error`, the one the SDK caught, + and those under it raised in the request; and the others under it, which are left as + they are and which the walk doesn't go past. `handled` and what is chained under it + are in neither: they are the application's. """ - chain: list[BaseException] = [] - seen: set[int] = set() - pending: list[BaseException | None] = [error] + scrub: list[BaseException] = [error] + left: list[BaseException] = [] + seen: set[int] = {id(error)} + if handled is not None: + seen.add(id(handled)) + pending = _chained(error) while pending: current = pending.pop() if current is None or id(current) in seen: continue seen.add(id(current)) if _raised_in_the_request(current): - chain.append(current) - pending += [current.__cause__, current.__context__] - return chain + scrub.append(current) + pending += _chained(current) + else: + left.append(current) + return scrub, left + + +# Text a builtin exception keeps in fields of its own, outside `__dict__` and `args`: a +# `UnicodeError`'s `object`, an `OSError`'s file names and `strerror`, a `SyntaxError`'s +# `text`. +_BUILTIN_TEXT_FIELDS = ("object", "filename", "filename2", "strerror", "text") + + +def _holds_key(error: BaseException) -> bool: + """Whether the text `error` keeps or shows holds a registered key.""" + shown = [str(error), repr(error.args), repr(getattr(error, "__dict__", {}))] + shown += [repr(getattr(error, name)) for name in _BUILTIN_TEXT_FIELDS if hasattr(error, name)] + return any(sdk_logger.scrub(text) != text for text in shown) + + +def _below(errors: list[BaseException], handled: BaseException | None) -> list[BaseException]: + """`errors` and everything chained under them, `handled` and what is under it apart.""" + found: list[BaseException] = [] + seen: set[int] = set() if handled is None else {id(handled)} + pending: list[BaseException | None] = list(errors) + while pending: + current = pending.pop() + if current is None or id(current) in seen: + continue + seen.add(id(current)) + found.append(current) + pending += _chained(current) + return found def _scrubbed_value(value: object) -> object: @@ -381,7 +433,7 @@ def _scrub_error_text(error: BaseException) -> bool: return scrubbed -def scrub_request_info(holder: object) -> bool: +def scrub_request_info(holder: object, *, handled: BaseException | None = None) -> bool: """Replace every client's API key in the request headers and error text `holder` keeps. aiohttp keeps the request's headers, `Authorization` included, on a @@ -393,28 +445,38 @@ def scrub_request_info(holder: object) -> bool: chained under it. The SDK puts such objects in the exceptions it raises (`original_error`, `response`, the exception's cause), so it scrubs them first. - Only what was raised within the request is changed (see `_raised_in_the_request`), - and only values that hold a key. A `ClientResponse`'s own URL, headers and body, and - values that aren't text, such as a parsed HTTP message, are left as they are. + Only values that hold a key are changed, in the error itself and in what was raised + within the request under it (see `_raised_in_the_request`). `handled`, the exception + the application was handling when it called the SDK, which aiohttp's errors keep as + their `__context__`, is left as it is, and so is everything chained under it. So are + a `ClientResponse`'s own URL, headers and body, and values that aren't text, such as a + parsed HTTP message. Args: holder: An aiohttp response or client error. + handled: The exception the application was handling when it called the SDK. Returns: - False if a value that holds a key could not be replaced; it never raises. + False if the key may still be in what `holder` keeps: a value that holds it could + not be replaced, or an exception left as it is holds it. It never raises. """ try: - return _scrub_chain(holder) if isinstance(holder, BaseException) else _scrub_holder(holder) + if isinstance(holder, BaseException): + return _scrub_chain(holder, handled) + return _scrub_holder(holder) except Exception: # noqa: BLE001 - a scrub that fails is reported, never raised return False -def _scrub_chain(error: BaseException) -> bool: +def _scrub_chain(error: BaseException, handled: BaseException | None) -> bool: scrubbed = True + to_scrub, left = _chain(error, handled) # Every one is scrubbed, even after one that could not be. - for chained in _chain(error): + for chained in to_scrub: scrubbed &= _scrub_holder(chained) - return scrubbed + # The key can still be where no write reaches: in text kept outside `__dict__` (a + # `UnicodeError`'s `object`), or in an exception left as it is, or under one. + return scrubbed and not any(_holds_key(shown) for shown in [*to_scrub, *_below(left, handled)]) def _scrub_holder(holder: object) -> bool: @@ -461,20 +523,26 @@ async def _error_json(response: aiohttp.ClientResponse) -> Any: # noqa: ANN401 Raises: PermitApiError: When the body is not JSON, whatever its Content-Type says. """ + handled = sys.exc_info()[1] + cause: aiohttp.ContentTypeError | None = None try: # The body is scrubbed before it is parsed too, so a decode error's `doc` never # holds the key. return _scrubbed(await response.json(loads=_scrubbed_loads)) except aiohttp.ContentTypeError as e: # Not chained to an error the key could not be removed from. - cause = e if scrub_request_info(e) else None - raise PermitApiError(response, {"details": await _scrubbed_text(response)}) from cause + if scrub_request_info(e, handled=handled): + cause = e except ValueError: # Labelled JSON but not JSON, such as a proxy's error page or a truncated body. - # A UnicodeDecodeError keeps the raw bytes, so the decode error isn't chained: - # raised after this block, it isn't the new exception's context either. - error = PermitApiError(response, {"details": await _scrubbed_text(response)}) - raise error + # A UnicodeDecodeError keeps the raw bytes, so the decode error isn't chained. + pass + # Raised after the `except` blocks, so the error caught there isn't the new + # exception's context. + error = PermitApiError(response, {"details": await _scrubbed_text(response)}) + if cause is None: + raise error + raise error from cause async def handle_api_error(response: aiohttp.ClientResponse) -> None: @@ -529,12 +597,15 @@ def handle_client_error( @functools.wraps(func) async def wrapped(*args: P.args, **kwargs: P.kwargs) -> R: + handled = sys.exc_info()[1] try: return await func(*args, **kwargs) except aiohttp.ClientError as err: sdk_logger.error(f"got client error while sending an http request:\n{err}") msg = f"{err}" - error = PermitConnectionError(msg, error=err) - raise error from error.original_error + error = PermitConnectionError(msg, error=err, handled=handled) + # Raised after the `except` block, so `err` isn't its context when it isn't + # attached. + raise error from error.original_error return wrapped diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py index 4ac0a04b..89a25dae 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -9,8 +9,10 @@ import dataclasses import inspect import json +import os import pprint import re +import socket import socketserver import subprocess import sys @@ -24,6 +26,7 @@ import aiohttp import pytest +from aiohttp import http_parser from loguru import logger from pytest_httpserver import HTTPServer from werkzeug import Request, Response @@ -1286,6 +1289,8 @@ def redirect_to(location: str) -> str: # InvalidUrlRedirectClientError with the URL parsed: a yarl URL in `_url` and `args`. pytest.param(redirect_to("http:///{key}"), id="redirect-url-without-host"), pytest.param(redirect_to("ftp://host/{key}"), id="non-http-redirect"), + # A ValueError raised in yarl, which keeps the host in its message. + pytest.param(redirect_to("http://{key}\u200bx/"), id="zero-width-space-in-redirect-host"), ] @@ -1322,9 +1327,10 @@ async def test_an_aiohttp_error_and_the_errors_chained_under_it_hold_no_key( assert caught.value.original_error is not None assert_holds_no_key(caught.value) - # The case still reaches a key to replace. + # The case still reaches a key to replace, in the aiohttp error or under it. shown = [ - repr(vars(chained)) + repr(chained.args) for chained in chained_exceptions(caught.value) + repr(vars(chained)) + repr(chained.args) + for chained in chained_exceptions(caught.value.original_error) ] assert REDACTED in "".join(shown) @@ -1350,6 +1356,13 @@ def raised(error): raise error except BaseException as caught: return caught + + +def calling(function): + try: + function() + except BaseException as caught: + return caught """ aiohttp_double = types.ModuleType("aiohttp._test_double") exec(AIOHTTP_DOUBLE_SOURCE, aiohttp_double.__dict__) # noqa: S102 - a fixed test double @@ -1454,10 +1467,7 @@ def args(self) -> tuple[object, ...]: # type: ignore[override] ) @pytest.mark.parametrize( "call", - [ - pytest.param(lambda permit: permit.check("user-1", "read", "document"), id="pdp"), - pytest.param(lambda permit: permit.api.users.get("user-1"), id="api"), - ], + [*LAZY_DEBUG_CALLS, pytest.param(lambda permit: permit.api.users.get("user-1"), id="api")], ) @pytest.mark.parametrize("client_class", CLIENT_CLASSES) @pytest.mark.parametrize( @@ -1492,7 +1502,10 @@ async def test_an_exception_the_application_is_handling_is_left_alone( assert (repr(vars(handled)), repr(handled.args)) == before if isinstance(handled, AppHeadersError): assert type(handled.headers) is dict + # The aiohttp error is attached: the application's exception, which holds the key, + # doesn't make the SDK fail closed. assert caught.value.original_error is not None + assert "not attached" not in str(caught.value.original_error) assert SENTINEL not in repr(vars(caught.value.original_error)) @@ -1510,7 +1523,7 @@ async def test_an_error_that_cannot_be_scrubbed_is_neither_attached_nor_the_caus call: Callable[[Permit], object], monkeypatch: pytest.MonkeyPatch, ) -> None: - monkeypatch.setattr("permit.exceptions.scrub_request_info", lambda _: False) + monkeypatch.setattr("permit.exceptions.scrub_request_info", lambda *_, **__: False) url = raw_http_server permit = client_class(PermitConfig(token=SENTINEL, api_url=url, pdp=url)) @@ -1520,4 +1533,278 @@ async def test_an_error_that_cannot_be_scrubbed_is_neither_attached_nor_the_caus replacement = caught.value.original_error assert "could not be removed" in str(replacement) assert caught.value.__cause__ is replacement + # Nor is the error that wasn't attached its context. + assert not any( + isinstance(chained, aiohttp.ClientError) and chained is not replacement + for chained in chained_exceptions(caught.value) + ) assert SENTINEL not in "".join(traceback.format_exception(caught.value)) + + +def closed_port() -> int: + """A port on 127.0.0.1 nothing listens on: a connection to it is refused.""" + with socket.socket() as probe: + probe.bind(("127.0.0.1", 0)) + return cast("int", probe.getsockname()[1]) + + +class AppStringHeadersError(Exception): + """An application's exception with a headers dict of strings, one holding the key.""" + + def __init__(self) -> None: + super().__init__(f"the application's own text, with the key {SENTINEL}") + self.headers = {"X-Echo": SENTINEL} + + +@pytest.mark.parametrize( + "call", + [*LAZY_DEBUG_CALLS, pytest.param(lambda permit: permit.api.users.get("user-1"), id="api")], +) +@pytest.mark.parametrize("client_class", CLIENT_CLASSES) +async def test_an_exception_the_application_is_handling_is_left_alone_on_a_refused_connection( + client_class: type[Permit], call: Callable[[Permit], object] +) -> None: + """A refused connection's `OSError` keeps the application's exception as its context. + + That is where the connection is refused at once, in the caller's task, as on Linux. + Where the refusal comes later from the event loop, as on macOS, the chain doesn't hold + it, and the redirect cases above are the ones that check this. + """ + url = f"http://127.0.0.1:{closed_port()}" + permit = client_class(PermitConfig(token=SENTINEL, api_url=url, pdp=url)) + handled = AppStringHeadersError() + headers = handled.headers + before = (repr(vars(handled)), repr(handled.args)) + + try: + raise_(handled) + except Exception: + with pytest.raises(PermitConnectionError) as caught: + await resolved(call(permit)) + + assert handled.headers is headers + assert (repr(vars(handled)), repr(handled.args)) == before + assert caught.value.original_error is not None + assert "not attached" not in str(caught.value.original_error) + + +@pytest.mark.parametrize( + "raw_http_server", + # yarl's IDNA encoding of the host fails in `idna`, a package the SDK doesn't change + # exceptions of, and that error keeps the host in its args. + [pytest.param(redirect_to("http://{key}ΓΌ..x/"), id="idna-error-in-a-redirect-host")], + indirect=True, +) +@pytest.mark.parametrize( + "call", + [ + pytest.param(lambda permit: permit.check("user-1", "read", "document"), id="pdp"), + pytest.param(lambda permit: permit.api.users.get("user-1"), id="api"), + ], +) +@pytest.mark.parametrize("client_class", CLIENT_CLASSES) +async def test_an_error_left_as_it_is_that_holds_the_key_is_not_attached( + raw_http_server: str, client_class: type[Permit], call: Callable[[Permit], object] +) -> None: + url = raw_http_server + permit = client_class(PermitConfig(token=SENTINEL, api_url=url, pdp=url)) + + with pytest.raises(PermitConnectionError) as caught: + await resolved(call(permit)) + + assert "could not be removed" in str(caught.value.original_error) + assert caught.value.__cause__ is caught.value.original_error + assert_holds_no_key(caught.value) + + +def test_the_pure_python_parser_is_in_use() -> None: + if os.environ.get("AIOHTTP_NO_EXTENSIONS") != "1": + pytest.skip("runs from test_the_raw_answers_hold_no_key_on_the_pure_python_parser") + + assert http_parser.HttpResponseParser is http_parser.HttpResponseParserPy + + +@pytest.mark.skipif( + os.environ.get("AIOHTTP_NO_EXTENSIONS") == "1", reason="this run already uses that parser" +) +def test_the_raw_answers_hold_no_key_on_the_pure_python_parser() -> None: + """The raw answers' cases, on the parser aiohttp uses when told not to use its C one. + + The two parsers' errors keep the server's text in different places. + """ + selected = [ + "test_the_pure_python_parser_is_in_use", + "test_an_aiohttp_error_and_the_errors_chained_under_it_hold_no_key", + "test_an_error_left_as_it_is_that_holds_the_key_is_not_attached", + ] + result = subprocess.run( + [ + sys.executable, + "-m", + "pytest", + __file__, + "-q", + "-p", + "no:cacheprovider", + "-k", + " or ".join(selected), + ], + env={**os.environ, "AIOHTTP_NO_EXTENSIONS": "1"}, + cwd=Path(__file__).parents[1], + capture_output=True, + text=True, + timeout=300, + check=False, + ) + + assert result.returncode == 0, result.stdout + result.stderr + passed = re.search(r"(\d+) passed", result.stdout) + assert passed is not None, result.stdout + assert int(passed.group(1)) == 1 + (len(RAW_ANSWERS) + 1) * 4, result.stdout + + +class _FixedArgsClientError(aiohttp.ClientError): + @property + def args(self) -> tuple[object, ...]: # type: ignore[override] + return (f"fixed {SENTINEL}",) + + +def test_a_bytearray_an_error_keeps_is_scrubbed(httpserver: HTTPServer) -> None: + Permit(make_config(httpserver)) + error = aiohttp_double.raised(aiohttp.ClientError(bytearray(f"line {SENTINEL}".encode()))) + + assert scrub_request_info(error) + + assert error.args == (bytearray(f"line {REDACTED}".encode()),) + + +def test_a_scrub_that_raises_reports_failure() -> None: + class HistoryRaises: + @property + def history(self) -> NoReturn: + raise RuntimeError(self) + + assert scrub_request_info(HistoryRaises()) is False + + +def test_the_errors_after_one_that_cannot_be_scrubbed_still_are(httpserver: HTTPServer) -> None: + Permit(make_config(httpserver)) + outer = aiohttp_double.raised(_FixedArgsClientError()) + inner = aiohttp_double.raised(aiohttp.ClientError(f"inner {SENTINEL}")) + outer.__cause__ = inner + + assert not scrub_request_info(outer) + + assert inner.args == (f"inner {REDACTED}",) + + +def test_text_a_builtin_exception_keeps_outside_its_args_fails_the_scrub( + httpserver: HTTPServer, +) -> None: + Permit(make_config(httpserver)) + outer = aiohttp_double.raised(aiohttp.ClientError("outer")) + undecodable = f"{SENTINEL}\xff".encode("latin-1") + outer.__cause__ = aiohttp_double.raised( + UnicodeDecodeError("utf-8", undecodable, len(SENTINEL), len(SENTINEL) + 1, "invalid") + ) + + # Its args are replaced, but its `object` can't be reached that way. + assert not scrub_request_info(outer) + + +def raise_application_error() -> NoReturn: + raise_(ValueError(f"the application's {SENTINEL}")) + + +def application_error_raised_from_aiohttp() -> BaseException: + # The first frame is aiohttp's, the frame that raised it the application's. + return cast("BaseException", aiohttp_double.calling(raise_application_error)) + + +def application_error_never_raised() -> BaseException: + return ValueError(f"the application's {SENTINEL}") + + +def key_held_under_an_application_error() -> BaseException: + middle = aiohttp_double.calling(lambda: raise_(ValueError("the application's"))) + middle.__cause__ = aiohttp_double.raised(aiohttp.ClientError(f"under it {SENTINEL}")) + return cast("BaseException", middle) + + +@pytest.mark.parametrize( + "under", + [ + pytest.param(application_error_raised_from_aiohttp, id="a-frame-of-the-applications"), + pytest.param(application_error_never_raised, id="no-traceback"), + pytest.param(key_held_under_an_application_error, id="the-key-under-it"), + ], +) +def test_an_error_that_is_not_the_requests_is_left_as_it_is_and_fails_the_scrub( + httpserver: HTTPServer, under: Callable[[], BaseException] +) -> None: + Permit(make_config(httpserver)) + outer = aiohttp_double.raised(aiohttp.ClientError("outer")) + outer.__cause__ = under() + before = [(repr(vars(chained)), repr(chained.args)) for chained in chained_exceptions(outer)] + + assert not scrub_request_info(outer) + + after = [(repr(vars(chained)), repr(chained.args)) for chained in chained_exceptions(outer)] + assert after == before + + +def test_the_exception_the_application_was_handling_does_not_fail_the_scrub( + httpserver: HTTPServer, +) -> None: + Permit(make_config(httpserver)) + handled = AppStringHeadersError() + try: + raise_(handled) + except AppStringHeadersError: + outer = aiohttp_double.raised(aiohttp.ClientError(f"outer {SENTINEL}")) + assert outer.__context__ is handled + before = (repr(vars(handled)), repr(handled.args)) + + assert scrub_request_info(outer, handled=handled) + + assert outer.args == (f"outer {REDACTED}",) + assert (repr(vars(handled)), repr(handled.args)) == before + + +@pytest.mark.parametrize("client_class", CLIENT_CLASSES) +async def test_a_content_type_error_that_cannot_be_scrubbed_is_not_chained( + httpserver: HTTPServer, client_class: type[Permit], monkeypatch: pytest.MonkeyPatch +) -> None: + httpserver.expect_request("/v2/api-key/scope", method="GET").respond_with_json( + {"organization_id": ORG_ID, "project_id": PROJECT_ID, "environment_id": ENV_ID} + ) + httpserver.expect_request(f"{USERS}/user-1", method="GET").respond_with_data( + "bad gateway", status=502, content_type="text/html" + ) + permit = client_class(make_config(httpserver)) + monkeypatch.setattr( + "permit.exceptions.scrub_request_info", + lambda holder, **_: not isinstance(holder, aiohttp.ContentTypeError), + ) + + with pytest.raises(PermitApiError) as caught: + await resolved(permit.api.users.get("user-1")) + + assert caught.value.__cause__ is None + assert not any( + isinstance(chained, aiohttp.ContentTypeError) + for chained in chained_exceptions(caught.value) + ) + + +def test_the_error_the_sdk_caught_is_scrubbed_whatever_its_frames(httpserver: HTTPServer) -> None: + Permit(make_config(httpserver)) + # Its traceback has a frame of this module's, which isn't one the request runs through. + caught: aiohttp.ClientError = aiohttp_double.calling( + lambda: raise_(aiohttp.ClientError(f"caught {SENTINEL}")) + ) + + error = PermitConnectionError("the request failed", error=caught) + + assert caught.args == (f"caught {REDACTED}",) + assert error.original_error is caught From 8914a72455b7f974f58286f692f9caee0b91ff05 Mon Sep 17 00:00:00 2001 From: Zeev Manilovich Date: Fri, 30 Oct 2026 16:36:19 +0200 Subject: [PATCH 16/17] PER-16680: walk the members of an exception group under an aiohttp error A traceback shows every member of an exception group and what is chained under each, so the scrub now walks them as it walks a cause and a context: members raised during the request are scrubbed, and a key in one left as it is fails the scrub. Works with the exceptiongroup backport on 3.10. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01TEQWbhLbnWSwco3H5iNFis --- README.md | 12 +++++----- permit/exceptions.py | 14 +++++++++-- tests/test_fix_logging.py | 50 +++++++++++++++++++++++++++++++++++++++ 3 files changed, 68 insertions(+), 8 deletions(-) diff --git a/README.md b/README.md index 445ee0e5..72ae6bb1 100644 --- a/README.md +++ b/README.md @@ -77,12 +77,12 @@ permit = Permit(token="", log={"enable": True, "level": "debug"}) - the messages of the exceptions it raises, and the error bodies in them (`PermitApiError.details`); - the aiohttp response or error those exceptions carry (`original_error`, `response`, - the cause), and the exceptions chained under that error that aiohttp and the - libraries it uses raised during the request: the request headers they keep, the - request headers of the redirect responses in their `history`, and each error's - arguments and attributes that are strings or bytes (such as its message), the - response headers it keeps, and the URL of an invalid-URL error (`InvalidURL.url`, - which then becomes a string). + the cause), and the exceptions chained under that error (as a cause or a context, or + as a member of an exception group) that aiohttp and the libraries it uses raised + during the request: the request headers they keep, the request headers of the + redirect responses in their `history`, and each error's arguments and attributes + that are strings or bytes (such as its message), the response headers it keeps, and + the URL of an invalid-URL error (`InvalidURL.url`, which then becomes a string). The SDK never changes an exception it did not raise during the request, such as one your application was handling when it called the SDK, which aiohttp keeps in its diff --git a/permit/exceptions.py b/permit/exceptions.py index 9f982f67..49359567 100644 --- a/permit/exceptions.py +++ b/permit/exceptions.py @@ -319,13 +319,23 @@ def _raised_in_the_request(error: BaseException) -> bool: def _chained(error: BaseException) -> list[BaseException | None]: - return [error.__cause__, error.__context__] + """The exceptions right under `error`: its cause and context, and a group's members. + + A traceback shows every member of an exception group, and what is chained under each. + The members are read from `exceptions`, which the exception groups of the backport for + Python 3.10 have too. + """ + chained: list[BaseException | None] = [error.__cause__, error.__context__] + members = getattr(error, "exceptions", None) + if isinstance(members, tuple): + chained += [member for member in members if isinstance(member, BaseException)] + return chained def _chain( error: BaseException, handled: BaseException | None ) -> tuple[list[BaseException], list[BaseException]]: - """The exceptions reachable from `error` through `__cause__` and `__context__`. + """The exceptions reachable from `error`, one `_chained` step at a time. Returns them in two lists: those to scrub, which are `error`, the one the SDK caught, and those under it raised in the request; and the others under it, which are left as diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py index 89a25dae..cefda15d 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -6,7 +6,9 @@ served by a local pytest_httpserver. """ +import builtins import dataclasses +import importlib import inspect import json import os @@ -1731,12 +1733,41 @@ def key_held_under_an_application_error() -> BaseException: return cast("BaseException", middle) +# A builtin from Python 3.11; on Python 3.10, the backport that pytest depends on there. +EXCEPTION_GROUP: Any = ( + getattr(builtins, "ExceptionGroup", None) + or importlib.import_module("exceptiongroup").ExceptionGroup +) + + +class _EchoClientError(aiohttp.ClientError): + """An aiohttp error with text in an attribute of its own, which its repr doesn't show.""" + + def __init__(self, echo: str) -> None: + super().__init__("echo") + self.echo = echo + + +def key_held_under_a_member_of_a_group() -> BaseException: + # The group is raised within the request, its member by the application. + member = key_held_under_an_application_error() + return cast("BaseException", aiohttp_double.raised(EXCEPTION_GROUP("group", [member]))) + + +def key_held_in_a_member_of_an_application_group() -> BaseException: + member = aiohttp_double.raised(_EchoClientError(f"Bearer {SENTINEL}")) + group = EXCEPTION_GROUP("the application's", [member]) + return cast("BaseException", aiohttp_double.calling(lambda: raise_(group))) + + @pytest.mark.parametrize( "under", [ pytest.param(application_error_raised_from_aiohttp, id="a-frame-of-the-applications"), pytest.param(application_error_never_raised, id="no-traceback"), pytest.param(key_held_under_an_application_error, id="the-key-under-it"), + pytest.param(key_held_under_a_member_of_a_group, id="the-key-under-a-group-member"), + pytest.param(key_held_in_a_member_of_an_application_group, id="the-key-in-a-group-member"), ], ) def test_an_error_that_is_not_the_requests_is_left_as_it_is_and_fails_the_scrub( @@ -1753,6 +1784,25 @@ def test_an_error_that_is_not_the_requests_is_left_as_it_is_and_fails_the_scrub( assert after == before +def test_the_members_of_an_exception_group_under_an_aiohttp_error_are_scrubbed( + httpserver: HTTPServer, +) -> None: + Permit(make_config(httpserver)) + member = aiohttp_double.raised(_EchoClientError(f"Bearer {SENTINEL}")) + member.__cause__ = aiohttp_double.raised(ValueError(f"under the member {SENTINEL}")) + outer = aiohttp_double.raised(aiohttp.ClientError("outer")) + outer.__cause__ = aiohttp_double.raised(EXCEPTION_GROUP("group", [member])) + + error = PermitConnectionError("the request failed", error=outer) + + assert error.original_error is outer + assert member.echo == f"Bearer {REDACTED}" + assert member.__cause__.args == (f"under the member {REDACTED}",) + # A traceback shows every member of a group, and what is chained under each. + shown = "".join(traceback.format_exception(outer)) + assert [key for key in SENTINEL_SPELLINGS if key in shown] == [] + + def test_the_exception_the_application_was_handling_does_not_fail_the_scrub( httpserver: HTTPServer, ) -> None: From 43454fd97764f20a0947455113030c24a2423d64 Mon Sep 17 00:00:00 2001 From: Zeev Manilovich Date: Fri, 30 Oct 2026 16:45:11 +0200 Subject: [PATCH 17/17] PER-16680: test the scrub paths the final key check would otherwise hide The check for a key the scrub could not reach also catches most write failures, so several tests passed whether or not the scrub worked. They now check that the error is attached where the scrub should succeed, and new cases cover: a write that fails out of sight of that check, an error without the key that can't be written to, a key held only in an error's text or only in its args, a cycle among the exceptions the scrub leaves as they are, and the exception the application was handling, under one left as it is, with frames only in the request's packages, and while an error body that isn't JSON is read. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01TEQWbhLbnWSwco3H5iNFis --- tests/test_fix_logging.py | 130 +++++++++++++++++++++++++++++++++++++- 1 file changed, 129 insertions(+), 1 deletion(-) diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py index cefda15d..505b0f95 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -30,8 +30,10 @@ import pytest from aiohttp import http_parser from loguru import logger +from multidict import CIMultiDict, CIMultiDictProxy from pytest_httpserver import HTTPServer from werkzeug import Request, Response +from yarl import URL import permit.logger as permit_logger from permit import Permit, PermitConfig @@ -1097,6 +1099,8 @@ async def test_a_connection_error_holds_no_key_from_the_aiohttp_error_text( # The aiohttp error's text is in the message, the key replaced. assert f"echo={REDACTED}" in str(error) assert_holds_no_key(error) + # The key is replaced in the response headers the error keeps, so it is attached. + assert isinstance(error.original_error, aiohttp.ContentTypeError) @pytest.mark.parametrize("client_class", CLIENT_CLASSES) @@ -1401,6 +1405,13 @@ def test_an_error_chained_only_as_the_context_is_scrubbed(httpserver: HTTPServer second.__cause__ = first assert scrub_request_info(first) print(first.args[0], second.args[0]) +# A cycle of exceptions the SDK leaves as it is, which it only checks for the key. +left = ValueError("left") +left.__cause__ = ValueError("under it") +left.__cause__.__cause__ = left +outer = double.raised(aiohttp.ClientError("outer")) +outer.__cause__ = left +print(scrub_request_info(outer)) """ @@ -1413,7 +1424,7 @@ def test_a_cause_cycle_is_walked_once(tmp_path: Path) -> None: ) assert result.returncode == 0, result.stderr - assert result.stdout.split() == ["first", REDACTED, "second", REDACTED] + assert result.stdout.split() == ["first", REDACTED, "second", REDACTED, "True"] def test_an_error_whose_text_cannot_be_replaced_is_not_attached(httpserver: HTTPServer) -> None: @@ -1432,6 +1443,46 @@ def args(self) -> tuple[object, ...]: # type: ignore[override] assert "could not be removed" in str(error.original_error) +class _FixedRequestInfoError(aiohttp.ClientError): + """An aiohttp error whose `request_info` can't be replaced, and which its text doesn't show.""" + + @property + def request_info(self) -> aiohttp.RequestInfo: + url = URL("http://127.0.0.1/") + headers = CIMultiDictProxy(CIMultiDict({"Authorization": f"Bearer {SENTINEL}"})) + return aiohttp.RequestInfo(url, "GET", headers, url) + + +def test_an_error_whose_request_headers_cannot_be_replaced_is_not_attached( + httpserver: HTTPServer, +) -> None: + Permit(make_config(httpserver)) + original = aiohttp_double.raised(_FixedRequestInfoError()) + + error = PermitConnectionError("the request failed", error=original) + + assert "could not be removed" in str(error.original_error) + + +@dataclasses.dataclass(frozen=True) +class _FrozenRequestError(Exception): + """An exception that can't be changed, with text and headers that hold no key.""" + + detail: str + headers: dict[str, str] + + +def test_an_error_without_the_key_is_not_written_to(httpserver: HTTPServer) -> None: + Permit(make_config(httpserver)) + original = aiohttp_double.raised(aiohttp.ClientError("outer")) + original.__cause__ = aiohttp_double.raised(_FrozenRequestError("no key", {"X-Id": "1"})) + + error = PermitConnectionError("the request failed", error=original) + + # Nothing is written to it: a write would fail, and the error wouldn't be attached. + assert error.original_error is original + + def raise_(error: BaseException) -> NoReturn: raise error @@ -1748,6 +1799,29 @@ def __init__(self, echo: str) -> None: self.echo = echo +class _ShowsTheKeyError(Exception): + """An exception whose text holds the key, which neither its args nor its attributes do.""" + + def __str__(self) -> str: + return f"shown {SENTINEL}" + + +def key_only_in_the_text_of_an_application_error() -> BaseException: + return cast("BaseException", aiohttp_double.calling(lambda: raise_(_ShowsTheKeyError()))) + + +class _HidesItsArgsError(Exception): + """An exception whose text doesn't show its args.""" + + def __str__(self) -> str: + return "hidden" + + +def key_only_in_the_args_of_an_application_error() -> BaseException: + error = _HidesItsArgsError(f"Bearer {SENTINEL}") + return cast("BaseException", aiohttp_double.calling(lambda: raise_(error))) + + def key_held_under_a_member_of_a_group() -> BaseException: # The group is raised within the request, its member by the application. member = key_held_under_an_application_error() @@ -1766,6 +1840,8 @@ def key_held_in_a_member_of_an_application_group() -> BaseException: pytest.param(application_error_raised_from_aiohttp, id="a-frame-of-the-applications"), pytest.param(application_error_never_raised, id="no-traceback"), pytest.param(key_held_under_an_application_error, id="the-key-under-it"), + pytest.param(key_only_in_the_text_of_an_application_error, id="the-key-in-its-text"), + pytest.param(key_only_in_the_args_of_an_application_error, id="the-key-in-its-args"), pytest.param(key_held_under_a_member_of_a_group, id="the-key-under-a-group-member"), pytest.param(key_held_in_a_member_of_an_application_group, id="the-key-in-a-group-member"), ], @@ -1821,6 +1897,35 @@ def test_the_exception_the_application_was_handling_does_not_fail_the_scrub( assert (repr(vars(handled)), repr(handled.args)) == before +def test_the_exception_the_application_was_handling_under_one_left_as_it_is_is_not_checked( + httpserver: HTTPServer, +) -> None: + Permit(make_config(httpserver)) + handled = AppStringHeadersError() + try: + raise_(handled) + except AppStringHeadersError: + # Raised outside the request's packages, as an event loop of another package does. + left = aiohttp_double.calling(lambda: raise_(ConnectionRefusedError("refused"))) + assert left.__context__ is handled + outer = aiohttp_double.raised(aiohttp.ClientError("outer")) + outer.__cause__ = left + + assert scrub_request_info(outer, handled=handled) + + +def test_the_exception_the_application_was_handling_is_left_alone_whatever_its_frames( + httpserver: HTTPServer, +) -> None: + Permit(make_config(httpserver)) + error = aiohttp_double.context_only(SENTINEL) + handled = error.__context__ + + assert scrub_request_info(error, handled=handled) + + assert handled.args == (f"inner {SENTINEL}",) + + @pytest.mark.parametrize("client_class", CLIENT_CLASSES) async def test_a_content_type_error_that_cannot_be_scrubbed_is_not_chained( httpserver: HTTPServer, client_class: type[Permit], monkeypatch: pytest.MonkeyPatch @@ -1847,6 +1952,29 @@ async def test_a_content_type_error_that_cannot_be_scrubbed_is_not_chained( ) +@pytest.mark.parametrize("client_class", CLIENT_CLASSES) +async def test_an_exception_the_application_is_handling_leaves_a_content_type_error_chained( + httpserver: HTTPServer, client_class: type[Permit] +) -> None: + httpserver.expect_request("/v2/api-key/scope", method="GET").respond_with_json( + {"organization_id": ORG_ID, "project_id": PROJECT_ID, "environment_id": ENV_ID} + ) + httpserver.expect_request(f"{USERS}/user-1", method="GET").respond_with_data( + "bad gateway", status=502, content_type="text/html" + ) + permit = client_class(make_config(httpserver)) + handled = AppStringHeadersError() + + try: + raise_(handled) + except AppStringHeadersError: + with pytest.raises(PermitApiError) as caught: + await resolved(permit.api.users.get("user-1")) + + # The application's exception holds the key, but it is the application's. + assert isinstance(caught.value.__cause__, aiohttp.ContentTypeError) + + def test_the_error_the_sdk_caught_is_scrubbed_whatever_its_frames(httpserver: HTTPServer) -> None: Permit(make_config(httpserver)) # Its traceback has a frame of this module's, which isn't one the request runs through.