From 2a6bd7bdc32c95ea011a1b20806cf443caa8bb0d Mon Sep 17 00:00:00 2001 From: Zeev Manilovich Date: Thu, 1 Oct 2026 12:50:15 +0300 Subject: [PATCH 01/32] Stop logging the API key when a client is created With log={"enable": True}, Permit() logged its whole config at DEBUG, token included, and the SDK did not apply log.level, so the API key reached the log whatever level was set (PER-16680). The line now names the API and PDP URLs only. Co-Authored-By: Claude Opus 5.5 --- permit/permit.py | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/permit/permit.py b/permit/permit.py index 51d6f51f..c0f15178 100644 --- a/permit/permit.py +++ b/permit/permit.py @@ -1,4 +1,3 @@ -import json from collections.abc import Generator from contextlib import contextmanager from typing import Any, Literal @@ -40,8 +39,7 @@ def __init__(self, config: PermitConfig | None = None, **options: Any) -> None: 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"})), + f"Permit SDK initialized: api_url={self._config.api_url}, pdp={self._config.pdp}" ) @property From 39f175fca0af299f452864e678e27f7ccdcbf2c5 Mon Sep 17 00:00:00 2001 From: Zeev Manilovich Date: Thu, 1 Oct 2026 12:54:06 +0300 Subject: [PATCH 02/32] Redact the API key from every record the SDK logs The SDK's own log lines no longer hold the key, but some records carry text from elsewhere: a PDP error body, an aiohttp error, a context the caller passed to a check. The SDK's records now go through permit.utils.sdk_logger, which replaces the API key of every client created in the process with [REDACTED] before handing the record to loguru, whether or not that client enabled logging (PER-16680). Records are still attributed to the SDK module that logged them, so logger.disable("permit") and the application's sinks see them as before. Co-Authored-By: Claude Opus 5.5 --- permit/api/base.py | 8 ++--- permit/api/context.py | 9 +++--- permit/enforcement/enforcer.py | 24 +++++++------- permit/exceptions.py | 4 +-- permit/logger.py | 7 ++++- permit/permit.py | 6 ++-- permit/utils/sdk_logger.py | 57 ++++++++++++++++++++++++++++++++++ 7 files changed, 88 insertions(+), 27 deletions(-) create mode 100644 permit/utils/sdk_logger.py 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/enforcement/enforcer.py b/permit/enforcement/enforcer.py index 119a5d4e..4b65de20 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: @@ -179,7 +179,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 +198,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 +207,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 +314,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 +339,7 @@ async def bulk_check( ), err, ) - logger.error(msg) + sdk_logger.error(msg) raise PermitConnectionError(msg, error=err) from err return decisions @@ -416,7 +416,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 +436,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 +445,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 +514,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 +522,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..3ea44040 100644 --- a/permit/logger.py +++ b/permit/logger.py @@ -1,6 +1,7 @@ from loguru import logger from permit.config import PermitConfig +from permit.utils.sdk_logger import sdk_logger PERMIT_MODULE = "permit" @@ -8,8 +9,12 @@ def configure_logger(config: PermitConfig) -> None: """Silence the SDK's loguru output unless the config enables logging. + Whatever the settings, the API key in `config.token` is replaced with `[REDACTED]` in + every record the SDK logs from now on, the records of other clients included. + Args: - config: The SDK configuration; only `config.log.enable` is read. + config: The SDK configuration; `config.log.enable` and `config.token` are read. """ + sdk_logger.redact(config.token) if not config.log.enable: logger.disable(PERMIT_MODULE) diff --git a/permit/permit.py b/permit/permit.py index c0f15178..b86302a5 100644 --- a/permit/permit.py +++ b/permit/permit.py @@ -2,7 +2,6 @@ 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 @@ -19,6 +18,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: @@ -38,7 +38,7 @@ def __init__(self, config: PermitConfig | None = None, **options: Any) -> None: self._api = PermitApiClient(self._config) self._elements = ElementsApi(self._config) self._pdp_api = PermitPdpApiClient(self._config) - logger.debug( + sdk_logger.debug( f"Permit SDK initialized: api_url={self._config.api_url}, pdp={self._config.pdp}" ) @@ -79,7 +79,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 diff --git a/permit/utils/sdk_logger.py b/permit/utils/sdk_logger.py new file mode 100644 index 00000000..56a13e82 --- /dev/null +++ b/permit/utils/sdk_logger.py @@ -0,0 +1,57 @@ +import threading + +from loguru import logger + +REDACTED = "[REDACTED]" + + +class SdkLogger: + """Logs the SDK's own records to loguru's logger, without the API keys in them. + + 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 replaces every registered API key with + `[REDACTED]`. + + The registered keys are process-wide, like loguru's logger. + """ + + def __init__(self) -> None: + self._secrets_lock = threading.Lock() + # Replaced, never mutated, so a thread that logs while another registers a secret + # reads either the old set or the new one. + self._secrets: frozenset[str] = frozenset() + + def redact(self, secret: str) -> None: + """Replace `secret` with `[REDACTED]` in every record logged from now on. + + Args: + secret: A credential, such as an API key. An empty string is ignored. + """ + if not secret: + return + with self._secrets_lock: + self._secrets |= {secret} + + 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: + for secret in self._secrets: + message = message.replace(secret, REDACTED) + # 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() From 074cf96f2676710daf7866efc5d5c67d686d113a Mon Sep 17 00:00:00 2001 From: Zeev Manilovich Date: Thu, 1 Oct 2026 12:51:28 +0300 Subject: [PATCH 03/32] Apply the log level and label to the SDK's records LoggerConfig's level and label had no effect (PER-16680): loguru's default sink printed every SDK record from DEBUG up, unlabelled. The SDK still adds no sink and leaves the application's sinks and levels alone. Instead, with log.enable True: - level drops the SDK's records below it before they reach any sink. Names are loguru's, in any case, plus warn and fatal. An unknown name raises ValueError when the client is created. - label is put in square brackets before every SDK message. - logger.enable("permit") is called, so a client that enables logging after one that disabled it is no longer silenced. log_as_json stays unapplied: loguru serializes per sink, and a JSON sink of the SDK's own would print every record a second time through loguru's default sink or the application's. The settings are process-wide, as loguru's logger is. With log.enable False nothing changes: the SDK calls logger.disable("permit") and reads no other setting. Co-Authored-By: Claude Opus 5.5 --- permit/logger.py | 44 ++++++++++++++++++++++++++++++++++---- permit/utils/sdk_logger.py | 26 ++++++++++++++++++---- 2 files changed, 62 insertions(+), 8 deletions(-) diff --git a/permit/logger.py b/permit/logger.py index 3ea44040..09bd4fb5 100644 --- a/permit/logger.py +++ b/permit/logger.py @@ -5,16 +5,52 @@ 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 calls + `logger.enable("permit")`. + - `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, with + `logger.add(..., serialize=True)`. - Whatever the settings, the API key in `config.token` is replaced with `[REDACTED]` in - every record the SDK logs from now on, the records of other clients included. + The API key in `config.token` is replaced with `[REDACTED]` in every record the SDK + logs, whatever the settings. Args: - config: The SDK configuration; `config.log.enable` and `config.token` are read. + config: The SDK configuration. + + Raises: + ValueError: If `log.enable` is True and `log.level` is not the name of a loguru level. """ sdk_logger.redact(config.token) if not config.log.enable: logger.disable(PERMIT_MODULE) + return + sdk_logger.configure(min_level_no=_level_no(config.log.level), label=config.log.label) + logger.enable(PERMIT_MODULE) + + +def _level_no(level: str) -> int: + name = level.upper() + name = _LEVEL_ALIASES.get(name, name) + try: + return logger.level(name).no + except ValueError: + msg = ( + f"Invalid log level {level!r} in the Permit SDK config (log.level): use trace, " + "debug, info, success, warning, error or critical, or a level added with " + "loguru's logger.level()." + ) + raise ValueError(msg) from None diff --git a/permit/utils/sdk_logger.py b/permit/utils/sdk_logger.py index 56a13e82..58086c88 100644 --- a/permit/utils/sdk_logger.py +++ b/permit/utils/sdk_logger.py @@ -6,22 +6,36 @@ class SdkLogger: - """Logs the SDK's own records to loguru's logger, without the API keys in them. + """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 replaces every registered API key with - `[REDACTED]`. + 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. - The registered keys are process-wide, like loguru's logger. + Its settings are process-wide, like loguru's logger. Until `configure` is called, it + keeps every record and adds no label. """ def __init__(self) -> None: + self._min_level_no = 0 + self._label = "" self._secrets_lock = threading.Lock() # Replaced, never mutated, so a thread that logs while another registers a secret # reads either the old set or the new one. self._secrets: frozenset[str] = frozenset() + def configure(self, *, min_level_no: int, label: str) -> None: + """Set the minimum severity of the records to keep and the label to prefix them with. + + 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 + def redact(self, secret: str) -> None: """Replace `secret` with `[REDACTED]` in every record logged from now on. @@ -46,8 +60,12 @@ def error(self, message: str) -> None: self._log("ERROR", message) def _log(self, level: str, message: str) -> None: + if logger.level(level).no < self._min_level_no: + return for secret in self._secrets: message = message.replace(secret, REDACTED) + 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. From 9965fedab854d81ffd057329c9cb94eb2123b5ad Mon Sep 17 00:00:00 2001 From: Zeev Manilovich Date: Thu, 1 Oct 2026 12:51:46 +0300 Subject: [PATCH 04/32] Document what each log option does LoggerConfig's descriptions said each option set something on "the Permit SDK Logger", which did not exist. They and a new Logging section in the README now say where the SDK's records go, what enable, level and label do, that json is not applied and how to get JSON from a loguru sink, that the settings are process-wide, and that no record holds the API key (PER-16680). Co-Authored-By: Claude Opus 5.5 --- README.md | 20 ++++++++++++++++++++ permit/config.py | 27 ++++++++++++++++++++++----- 2 files changed, 42 insertions(+), 5 deletions(-) diff --git a/README.md b/README.md index e249ce14..56e167f3 100644 --- a/README.md +++ b/README.md @@ -40,6 +40,26 @@ 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. +- `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. +- `label` (default `"Permit"`) is put in square brackets before every message the SDK logs. +- `json` is not applied: for JSON output, add a sink with `logger.add(sys.stderr, serialize=True)`. +- 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. +- No record the SDK logs contains the API key. + ## Deprecations A future major release, permit 4.0, will remove the following. They still work in 3.x, and diff --git a/permit/config.py b/permit/config.py index 7a42f941..f842ee1d 100644 --- a/permit/config.py +++ b/permit/config.py @@ -13,22 +13,39 @@ 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. No record the SDK logs + contains the API key: it is replaced with `[REDACTED]`. + """ 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 calls logger.enable('permit').", ) 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; a name loguru does not know raises ValueError when the " + "client is created.", ) 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, add a sink with logger.add(..., serialize=True).", ) From 457ca087e8e585097eee3061e42bb8eff8c2fe5c Mon Sep 17 00:00:00 2001 From: Zeev Manilovich Date: Thu, 1 Oct 2026 12:52:11 +0300 Subject: [PATCH 05/32] Test that the SDK never logs its API key and applies log settings Offline tests for PER-16680, with loguru sinks added the way an application adds them: a stderr sink in loguru's default format and a JSON sink, both at DEBUG. For the async and the blocking client, at level debug, info and unset, with json on and off, they go through every kind of record the SDK logs and find neither the API key nor a [REDACTED] marker. They also check that a key a PDP echoes back is redacted, that level drops the SDK's records and no others, that label prefixes every SDK message, that json leaves the format to the sinks, that a disabled client logs nothing, that the client created last decides, and that creating 40 clients adds no sink. Each test starts from a fresh SdkLogger and puts loguru's permit switch back the way it found it. Co-Authored-By: Claude Opus 5.5 --- tests/test_fix_logging.py | 433 ++++++++++++++++++++++++++++++++++++++ 1 file changed, 433 insertions(+) create mode 100644 tests/test_fix_logging.py diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py new file mode 100644 index 00000000..2a520e55 --- /dev/null +++ b/tests/test_fix_logging.py @@ -0,0 +1,433 @@ +"""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 sys +import types +from collections.abc import Iterator +from dataclasses import dataclass, field +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 from a fresh SdkLogger, and put both it and loguru's permit switch back after.""" + was_enabled = _permit_records_enabled() + saved = vars(sdk_logger).copy() + vars(sdk_logger).update(vars(SdkLogger())) + 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) + + +@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: + def echo_the_key(request: Request) -> Response: + return Response(f"rejected key: {request.headers['Authorization']}", status=403) + + 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): + 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() + + +@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()] + + +def test_an_unknown_level_fails_when_the_client_is_created(httpserver: HTTPServer) -> None: + with pytest.raises(ValueError, match=r"Invalid log level 'verbose'"): + SyncPermit(make_config(httpserver, enable=True, level="verbose")) + + +@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) + + +def test_an_empty_api_key_redacts_nothing(httpserver: HTTPServer, app_sinks: AppSinks) -> None: + with SyncPermit(make_config(httpserver, 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_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 eaf1722c887df590f82afc74c0531dec9cfb089c Mon Sep 17 00:00:00 2001 From: Zeev Manilovich Date: Thu, 1 Oct 2026 13:00:47 +0300 Subject: [PATCH 06/32] Accept a lower-case log level the application added to loguru loguru's level names are case-sensitive, and log.level was looked up only in upper case, so a level such as logger.level("audit", no=35) raised ValueError although the error message offers levels added with logger.level(). Try the name as given first, then the upper-case name. Co-Authored-By: Claude Opus 5.5 --- permit/logger.py | 25 ++++++++++--------- tests/test_fix_logging.py | 52 +++++++++++++++++++++++++++++++++++++++ 2 files changed, 66 insertions(+), 11 deletions(-) diff --git a/permit/logger.py b/permit/logger.py index 09bd4fb5..d0fc4c8a 100644 --- a/permit/logger.py +++ b/permit/logger.py @@ -1,3 +1,5 @@ +import contextlib + from loguru import logger from permit.config import PermitConfig @@ -43,14 +45,15 @@ def configure_logger(config: PermitConfig) -> None: def _level_no(level: str) -> int: - name = level.upper() - name = _LEVEL_ALIASES.get(name, name) - try: - return logger.level(name).no - except ValueError: - msg = ( - f"Invalid log level {level!r} in the Permit SDK config (log.level): use trace, " - "debug, info, success, warning, error or critical, or a level added with " - "loguru's logger.level()." - ) - raise ValueError(msg) from 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 + msg = ( + f"Invalid log level {level!r} in the Permit SDK config (log.level): use trace, " + "debug, info, success, warning, error or critical, or a level added with " + "loguru's logger.level()." + ) + raise ValueError(msg) diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py index 2a520e55..50c98b8d 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -7,10 +7,12 @@ """ import json +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 @@ -284,6 +286,56 @@ def test_an_unknown_level_fails_when_the_client_is_created(httpserver: HTTPServe SyncPermit(make_config(httpserver, enable=True, level="verbose")) +# 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"), [ From 0a0cbbc951afa935464852dacf523e58495c16a2 Mon Sep 17 00:00:00 2001 From: Zeev Manilovich Date: Thu, 1 Oct 2026 13:00:58 +0300 Subject: [PATCH 07/32] Say in the README what the log level hides and when it raises Co-Authored-By: Claude Opus 5.5 --- README.md | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/README.md b/README.md index 56e167f3..1c63fadb 100644 --- a/README.md +++ b/README.md @@ -52,7 +52,9 @@ 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. - `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. + 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`, a level name loguru + does not know raises `ValueError` when the client is created. - `label` (default `"Permit"`) is put in square brackets before every message the SDK logs. - `json` is not applied: for JSON output, add a sink with `logger.add(sys.stderr, serialize=True)`. - loguru's logger is process-wide, so these settings are too: the client created last From ef40ecdc39c73716ad987a82e4cc44fbd3354f8a Mon Sep 17 00:00:00 2001 From: Zeev Manilovich Date: Thu, 1 Oct 2026 13:23:28 +0300 Subject: [PATCH 08/32] Hide the API key from PermitConfig's repr An unknown log level now raises ValueError while the client is created. An application that logs that failure with loguru's logger.exception (diagnose=True by default) printed the config's repr from the SDK's frames, and with it the API key. repr=False keeps the token out of repr() and str() of the config; the field itself is unchanged. Co-Authored-By: Claude Opus 5.5 --- permit/config.py | 3 +++ tests/test_fix_logging.py | 23 +++++++++++++++++++++++ 2 files changed, 26 insertions(+) diff --git a/permit/config.py b/permit/config.py index f842ee1d..2ffc9a99 100644 --- a/permit/config.py +++ b/permit/config.py @@ -71,8 +71,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/tests/test_fix_logging.py b/tests/test_fix_logging.py index 50c98b8d..636f8786 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -286,6 +286,29 @@ def test_an_unknown_level_fails_when_the_client_is_created(httpserver: HTTPServe SyncPermit(make_config(httpserver, enable=True, level="verbose")) +def test_the_traceback_of_a_failed_client_creation_hides_the_api_key( + httpserver: HTTPServer, +) -> None: + 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, level="verbose") + try: + try: + SyncPermit(config) + except ValueError: + 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 1bb2a3235b00338aaab47785d51dfd6101bb3f14 Mon Sep 17 00:00:00 2001 From: Zeev Manilovich Date: Thu, 1 Oct 2026 13:35:33 +0300 Subject: [PATCH 09/32] Redact the longest registered API key first The keys were kept in a frozenset and replaced in its iteration order, which depends on the hash seed. When a key that is a prefix of another was replaced first, the rest of the longer key stayed in the record. Keep the keys in a tuple sorted longest first, and move the replacement into SdkLogger.scrub(). Co-Authored-By: Claude Opus 5.5 --- permit/utils/sdk_logger.py | 27 +++++++++++++++++++++------ tests/test_fix_logging.py | 25 ++++++++++++++++++++++--- 2 files changed, 43 insertions(+), 9 deletions(-) diff --git a/permit/utils/sdk_logger.py b/permit/utils/sdk_logger.py index 58086c88..5b3a11ed 100644 --- a/permit/utils/sdk_logger.py +++ b/permit/utils/sdk_logger.py @@ -22,9 +22,11 @@ def __init__(self) -> None: self._min_level_no = 0 self._label = "" self._secrets_lock = threading.Lock() - # Replaced, never mutated, so a thread that logs while another registers a secret - # reads either the old set or the new one. - self._secrets: frozenset[str] = frozenset() + # 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 configure(self, *, min_level_no: int, label: str) -> None: """Set the minimum severity of the records to keep and the label to prefix them with. @@ -45,7 +47,21 @@ def redact(self, secret: str) -> None: if not secret: return with self._secrets_lock: - self._secrets |= {secret} + if secret not in self._secrets: + self._secrets = tuple(sorted((*self._secrets, secret), 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.""" @@ -62,8 +78,7 @@ def error(self, message: str) -> None: def _log(self, level: str, message: str) -> None: if logger.level(level).no < self._min_level_no: return - for secret in self._secrets: - message = message.replace(secret, REDACTED) + 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 diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py index 636f8786..8d663e72 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -232,13 +232,15 @@ def test_sync_client_never_logs_the_api_key( 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: - def echo_the_key(request: Request) -> Response: - return Response(f"rejected key: {request.headers['Authorization']}", status=403) - httpserver.expect_request("/allowed", method="POST").respond_with_handler(echo_the_key) if enabled_by == "config": permit = Permit(make_config(httpserver, enable=True)) @@ -255,6 +257,23 @@ def echo_the_key(request: Request) -> Response: assert SENTINEL not in app_sinks.everything() +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() + + @pytest.mark.parametrize( ("log", "expected_levels"), [ From e9100d2ce75c9dce38cd0509316c93e540a43108 Mon Sep 17 00:00:00 2001 From: Zeev Manilovich Date: Thu, 1 Oct 2026 13:36:09 +0300 Subject: [PATCH 10/32] Also redact the API key without surrounding whitespace A key read from a file or an environment variable may end with a space. aiohttp sends it, and a PDP that echoes the key back returns it trimmed, so the exact-match replacement missed it. Register the trimmed key as well, and ignore a key that is only whitespace, which would otherwise replace every space in the SDK's messages. Co-Authored-By: Claude Opus 5.5 --- permit/utils/sdk_logger.py | 15 +++++++++++---- tests/test_fix_logging.py | 21 +++++++++++++++++++-- 2 files changed, 30 insertions(+), 6 deletions(-) diff --git a/permit/utils/sdk_logger.py b/permit/utils/sdk_logger.py index 5b3a11ed..72d70787 100644 --- a/permit/utils/sdk_logger.py +++ b/permit/utils/sdk_logger.py @@ -41,14 +41,21 @@ def configure(self, *, min_level_no: int, label: str) -> None: 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. An empty string is ignored. + secret: A credential, such as an API key. A secret that is empty or only + whitespace is ignored. """ - if not secret: + trimmed = secret.strip() + if not trimmed: return with self._secrets_lock: - if secret not in self._secrets: - self._secrets = tuple(sorted((*self._secrets, secret), key=len, reverse=True)) + 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]`. diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py index 8d663e72..c9ac9bca 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -274,6 +274,20 @@ async def test_a_key_is_redacted_whole_when_another_key_is_a_prefix_of_it( 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"), [ @@ -406,8 +420,11 @@ def test_an_empty_label_adds_no_prefix(httpserver: HTTPServer, app_sinks: AppSin assert record["message"].startswith(WAIT_FOR_SYNC_WARNING) -def test_an_empty_api_key_redacts_nothing(httpserver: HTTPServer, app_sinks: AppSinks) -> None: - with SyncPermit(make_config(httpserver, token="", enable=True)).wait_for_sync(): +@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() From 9d02291a7e2656da97bc8e9a1c5ef1a24d23496b Mon Sep 17 00:00:00 2001 From: Zeev Manilovich Date: Thu, 1 Oct 2026 13:36:51 +0300 Subject: [PATCH 11/32] Redact the API key from PDP error bodies the SDK raises The SDK replaced a key the PDP echoed back in its own error record, then raised PermitConnectionError with the same body unchanged, so an application that logged or reported the exception wrote the key. Scrub the body where it is read, which covers check, bulk_check and authorized_users, and say in the docs what is and is not replaced. Co-Authored-By: Claude Opus 5.5 --- README.md | 5 ++++- permit/config.py | 8 ++++++-- permit/enforcement/enforcer.py | 8 ++++++++ permit/logger.py | 5 +++-- tests/test_fix_logging.py | 31 ++++++++++++++++++++++++++++++- 5 files changed, 51 insertions(+), 6 deletions(-) diff --git a/README.md b/README.md index 1c63fadb..aa11624d 100644 --- a/README.md +++ b/README.md @@ -60,7 +60,10 @@ permit = Permit(token="", log={"enable": True, "level": "debug"}) - 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. -- No record the SDK logs contains the API key. +- 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 diff --git a/permit/config.py b/permit/config.py index 2ffc9a99..73210b49 100644 --- a/permit/config.py +++ b/permit/config.py @@ -19,8 +19,12 @@ class LoggerConfig(BaseModel): 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. No record the SDK logs - contains the API key: it is replaced with `[REDACTED]`. + 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( diff --git a/permit/enforcement/enforcer.py b/permit/enforcement/enforcer.py index 4b65de20..c9d51027 100644 --- a/permit/enforcement/enforcer.py +++ b/permit/enforcement/enforcer.py @@ -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): diff --git a/permit/logger.py b/permit/logger.py index d0fc4c8a..0c30bfbb 100644 --- a/permit/logger.py +++ b/permit/logger.py @@ -27,8 +27,9 @@ def configure_logger(config: PermitConfig) -> None: - `log.log_as_json` is not applied: loguru serializes per sink, with `logger.add(..., serialize=True)`. - The API key in `config.token` is replaced with `[REDACTED]` in every record the SDK - logs, whatever the settings. + 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`. Args: config: The SDK configuration. diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py index c9ac9bca..9b7e1fe0 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -249,12 +249,41 @@ async def test_an_api_key_the_pdp_echoes_back_is_redacted( permit = Permit(make_config(httpserver)) logger.enable("permit") - with pytest.raises(PermitConnectionError): + 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( From 99ca527bb19582323e0d9d268883670349eec672 Mon Sep 17 00:00:00 2001 From: Zeev Manilovich Date: Thu, 1 Oct 2026 13:38:23 +0300 Subject: [PATCH 12/32] Undo only the SDK's own logger.disable when logging is enabled Every client created with log.enable True called logger.enable("permit"). In loguru that also drops every disable the application set for a module of the package, and overrides an application-wide logger.disable(""). Now the SDK calls logger.enable("permit") only to undo a logger.disable("permit") that an earlier client made, which keeps the fix for an enabled client created after a disabled one. Co-Authored-By: Claude Opus 5.5 --- README.md | 4 ++++ permit/config.py | 4 +++- permit/logger.py | 15 ++++++++------- permit/utils/sdk_logger.py | 23 ++++++++++++++++++++--- tests/test_fix_logging.py | 32 +++++++++++++++++++++++++++++++- 5 files changed, 66 insertions(+), 12 deletions(-) diff --git a/README.md b/README.md index aa11624d..8b13e4b5 100644 --- a/README.md +++ b/README.md @@ -51,6 +51,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. - `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`, a level name loguru diff --git a/permit/config.py b/permit/config.py index 73210b49..e3dd2b7b 100644 --- a/permit/config.py +++ b/permit/config.py @@ -30,7 +30,9 @@ class LoggerConfig(BaseModel): enable: bool = Field( default=False, description="Whether the SDK logs. False calls loguru's logger.disable('permit'), so " - "nothing is logged; True calls logger.enable('permit').", + "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", diff --git a/permit/logger.py b/permit/logger.py index 0c30bfbb..45350a32 100644 --- a/permit/logger.py +++ b/permit/logger.py @@ -3,9 +3,9 @@ from loguru import logger from permit.config import PermitConfig -from permit.utils.sdk_logger import sdk_logger +from permit.utils.sdk_logger import PACKAGE, sdk_logger -PERMIT_MODULE = "permit" +PERMIT_MODULE = PACKAGE # The names Python's logging module also accepts, and the ones the Node SDK's logger uses. _LEVEL_ALIASES = {"WARN": "WARNING", "FATAL": "CRITICAL"} @@ -20,8 +20,10 @@ def configure_logger(config: PermitConfig) -> None: 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 calls - `logger.enable("permit")`. + - `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, with @@ -39,10 +41,9 @@ def configure_logger(config: PermitConfig) -> None: """ sdk_logger.redact(config.token) if not config.log.enable: - logger.disable(PERMIT_MODULE) + sdk_logger.disable() return - sdk_logger.configure(min_level_no=_level_no(config.log.level), label=config.log.label) - logger.enable(PERMIT_MODULE) + sdk_logger.enable(min_level_no=_level_no(config.log.level), label=config.log.label) def _level_no(level: str) -> int: diff --git a/permit/utils/sdk_logger.py b/permit/utils/sdk_logger.py index 72d70787..07faed11 100644 --- a/permit/utils/sdk_logger.py +++ b/permit/utils/sdk_logger.py @@ -3,6 +3,8 @@ 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: @@ -14,13 +16,15 @@ class SdkLogger: 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 `configure` is called, it + 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, @@ -28,8 +32,18 @@ def __init__(self) -> None: # either the old tuple or the new one. self._secrets: tuple[str, ...] = () - def configure(self, *, min_level_no: int, label: str) -> None: - """Set the minimum severity of the records to keep and the label to prefix them with. + 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. @@ -37,6 +51,9 @@ def configure(self, *, min_level_no: int, label: str) -> 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. diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py index 9b7e1fe0..416b046c 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -58,10 +58,15 @@ def _permit_records_enabled() -> bool: @pytest.fixture(autouse=True) def isolated_logging() -> Iterator[None]: - """Start from a fresh SdkLogger, and put both it and loguru's permit switch back after.""" + """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: @@ -535,6 +540,31 @@ def test_the_client_created_last_decides_whether_the_sdk_logs( 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 test_the_application_can_still_turn_the_sdk_records_on_itself( httpserver: HTTPServer, app_sinks: AppSinks ) -> None: From abd47f256b31616d7ee033b6de5ea3a7f4466107 Mon Sep 17 00:00:00 2001 From: Zeev Manilovich Date: Thu, 1 Oct 2026 13:41:02 +0300 Subject: [PATCH 13/32] Keep the process's log settings when wait_for_sync is used wait_for_sync() created a new client from the config, which ran configure_logger again on every call. That turned SDK logging back on after a client created later with logging disabled, and reset the level and label. It now yields a copy of the client whose PDP and API clients are rebuilt from the new config, through the _connect() hook the blocking client overrides. Co-Authored-By: Claude Opus 5.5 --- README.md | 3 +- permit/permit.py | 18 +++++++--- permit/sync.py | 2 ++ tests/test_fix_logging.py | 73 +++++++++++++++++++++++++++++++++++++++ 4 files changed, 91 insertions(+), 5 deletions(-) diff --git a/README.md b/README.md index 8b13e4b5..faf1d22b 100644 --- a/README.md +++ b/README.md @@ -63,7 +63,8 @@ permit = Permit(token="", log={"enable": True, "level": "debug"}) - `json` is not applied: for JSON output, add a sink with `logger.add(sys.stderr, serialize=True)`. - 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. + 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 diff --git a/permit/permit.py b/permit/permit.py index b86302a5..a636a05c 100644 --- a/permit/permit.py +++ b/permit/permit.py @@ -1,3 +1,4 @@ +import copy from collections.abc import Generator from contextlib import contextmanager from typing import Any, Literal @@ -34,13 +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) - sdk_logger.debug( - f"Permit SDK initialized: api_url={self._config.api_url}, pdp={self._config.pdp}" - ) @property def config(self) -> PermitConfig: @@ -88,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/tests/test_fix_logging.py b/tests/test_fix_logging.py index 416b046c..8ffef168 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -7,6 +7,7 @@ """ import json +import re import subprocess import sys import types @@ -565,6 +566,78 @@ def test_an_enabled_client_keeps_a_disable_the_application_set_for_the_sdk( 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: From 8f3af5bace37091a15096fb737b2ca198c5c8f6e Mon Sep 17 00:00:00 2001 From: Zeev Manilovich Date: Thu, 1 Oct 2026 13:41:30 +0300 Subject: [PATCH 14/32] Show the JSON log recipe in place of loguru's default sink The documented logger.add(sys.stderr, serialize=True) keeps loguru's default text sink, so every record was printed twice, once as text and once as JSON. Say that the application replaces the default sink with logger.remove() first, in the README, the log_as_json description and the configure_logger docstring. Co-Authored-By: Claude Opus 5.5 --- README.md | 4 +++- permit/config.py | 3 ++- permit/logger.py | 5 +++-- 3 files changed, 8 insertions(+), 4 deletions(-) diff --git a/README.md b/README.md index faf1d22b..167b42e6 100644 --- a/README.md +++ b/README.md @@ -60,7 +60,9 @@ permit = Permit(token="", log={"enable": True, "level": "debug"}) requests and the PDP's responses at `"debug"`. With `"enable": True`, a level name loguru does not know raises `ValueError` when the client is created. - `label` (default `"Permit"`) is put in square brackets before every message the SDK logs. -- `json` is not applied: for JSON output, add a sink with `logger.add(sys.stderr, serialize=True)`. +- `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 diff --git a/permit/config.py b/permit/config.py index e3dd2b7b..9332f280 100644 --- a/permit/config.py +++ b/permit/config.py @@ -51,7 +51,8 @@ class LoggerConfig(BaseModel): default=False, alias="json", description="Not applied. The format of the SDK's records is that of the loguru sinks " - "they reach: for JSON, add a sink with logger.add(..., serialize=True).", + "they reach. For JSON, the application replaces loguru's default sink with a " + "serialized one: logger.remove(), then logger.add(sys.stderr, serialize=True).", ) diff --git a/permit/logger.py b/permit/logger.py index 45350a32..04725320 100644 --- a/permit/logger.py +++ b/permit/logger.py @@ -26,8 +26,9 @@ def configure_logger(config: PermitConfig) -> None: 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, with - `logger.add(..., serialize=True)`. + - `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 From 5dfe91f99fa83df92ba51859d6feec0c3a187e3f Mon Sep 17 00:00:00 2001 From: Zeev Manilovich Date: Thu, 1 Oct 2026 13:41:57 +0300 Subject: [PATCH 15/32] Ban direct use of loguru's logger in the SDK package The API key redaction and the log level and label hold only while every SDK log call goes through permit.utils.sdk_logger. A ruff banned-api rule (TID251) now flags loguru.logger anywhere in permit/ except the wrapper itself and permit/logger.py, which reads loguru's levels. Co-Authored-By: Claude Opus 5.5 --- pyproject.toml | 8 ++++++++ 1 file changed, 8 insertions(+) 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" = [ From 3e3688782791eb963ecabb8261637a60d58fcc92 Mon Sep 17 00:00:00 2001 From: Zeev Manilovich Date: Thu, 1 Oct 2026 14:26:35 +0300 Subject: [PATCH 16/32] Warn and log at INFO for an unknown log level instead of raising An unknown log.level was ignored before this branch, so raising ValueError at client creation would break an app on upgrade. The SDK now logs a warning that names the value and uses INFO. The traceback test forces a failure inside configure_logger instead, and still checks that the API key never shows. Co-Authored-By: Claude Opus 5.5 --- README.md | 4 ++-- permit/config.py | 4 ++-- permit/logger.py | 26 +++++++++++++++----------- tests/test_fix_logging.py | 31 +++++++++++++++++++++++++------ 4 files changed, 44 insertions(+), 21 deletions(-) diff --git a/README.md b/README.md index 167b42e6..01e3ed49 100644 --- a/README.md +++ b/README.md @@ -57,8 +57,8 @@ permit = Permit(token="", log={"enable": True, "level": "debug"}) 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`, a level name loguru - does not know raises `ValueError` when the client is created. + 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)`. diff --git a/permit/config.py b/permit/config.py index 9332f280..490c6576 100644 --- a/permit/config.py +++ b/permit/config.py @@ -39,8 +39,8 @@ class LoggerConfig(BaseModel): 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; a name loguru does not know raises ValueError when the " - "client is created.", + "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", diff --git a/permit/logger.py b/permit/logger.py index 04725320..48f35113 100644 --- a/permit/logger.py +++ b/permit/logger.py @@ -34,29 +34,33 @@ def configure_logger(config: PermitConfig) -> None: 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. - - Raises: - ValueError: If `log.enable` is True and `log.level` is not the name of a loguru level. """ sdk_logger.redact(config.token) if not config.log.enable: sdk_logger.disable() return - sdk_logger.enable(min_level_no=_level_no(config.log.level), label=config.log.label) + 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: +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 - msg = ( - f"Invalid log level {level!r} in the Permit SDK config (log.level): use trace, " - "debug, info, success, warning, error or critical, or a level added with " - "loguru's logger.level()." - ) - raise ValueError(msg) + return None diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py index 8ffef168..5422f424 100644 --- a/tests/test_fix_logging.py +++ b/tests/test_fix_logging.py @@ -349,23 +349,42 @@ async def test_level_drops_the_sdk_records_below_it( assert "an application record" in [record["message"] for record in app_sinks.records()] -def test_an_unknown_level_fails_when_the_client_is_created(httpserver: HTTPServer) -> None: - with pytest.raises(ValueError, match=r"Invalid log level 'verbose'"): - SyncPermit(make_config(httpserver, enable=True, level="verbose")) +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, + 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, level="verbose") + config = make_config(httpserver, enable=True) try: try: SyncPermit(config) - except ValueError: + except RuntimeError: logger.exception("the application could not start") finally: logger.remove(sink_id) From 0d4c016efdae7fc27fd0e17e06f7bcbcc070301d Mon Sep 17 00:00:00 2001 From: eli Date: Tue, 27 Oct 2026 18:27:17 -0500 Subject: [PATCH 17/32] 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 (cherry picked from commit ec418761e406281bba17804492026d7e8adb28d9) --- 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 e4c411c58a471164b0e9355af99f5db2d2bd8fd6 Mon Sep 17 00:00:00 2001 From: eli Date: Wed, 28 Oct 2026 13:05:25 -0500 Subject: [PATCH 18/32] 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 (cherry picked from commit 65cc6705b58f303f5ffdf06f013434195960cc1a) --- 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 efbd68a41166b3ab44aa333e8872b13867af56a9 Mon Sep 17 00:00:00 2001 From: eli Date: Wed, 28 Oct 2026 14:37:28 -0500 Subject: [PATCH 19/32] 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 (cherry picked from commit 9758ab58ea08b632049943e7290fed0b6e6ff662) --- 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 dbd45b812cebb45d9bfb33ed33c47c2bc39c43c4 Mon Sep 17 00:00:00 2001 From: eli Date: Wed, 28 Oct 2026 14:51:33 -0500 Subject: [PATCH 20/32] 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 (cherry picked from commit fbc59c043782d2b6a12245b6410019d41f03fdd9) --- 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 948c2d45715ac9268c36f3bbf86bb0c0a79c7dd2 Mon Sep 17 00:00:00 2001 From: eli Date: Thu, 29 Oct 2026 13:13:47 -0500 Subject: [PATCH 21/32] 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 (cherry picked from commit 8d02edee66a9dd6c608607fc9ac833a8f86dc9e6) --- 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 76414774c86d6e0ed538bc93c2036fcf99fe4d6c Mon Sep 17 00:00:00 2001 From: eli Date: Thu, 29 Oct 2026 13:13:47 -0500 Subject: [PATCH 22/32] 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 (cherry picked from commit b5de9d14c08b1c5125d5602e153b74bc1f9da58d) --- 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 7de2993926074cabf215ff6b803d0e1cd8e345af Mon Sep 17 00:00:00 2001 From: eli Date: Thu, 29 Oct 2026 13:16:48 -0500 Subject: [PATCH 23/32] 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 (cherry picked from commit a8bf8c266b636a5b6b303a3bf6de250097240992) --- 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 a3aac1bd6dfaf24bd0cc004478f4002351709de6 Mon Sep 17 00:00:00 2001 From: eli Date: Thu, 29 Oct 2026 13:18:58 -0500 Subject: [PATCH 24/32] 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 (cherry picked from commit bce21180a07e980a6ea093ebad6f9471c2eeb363) --- 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 f0e74c5bd106f17347db2a1f45a87f39679e3f2b Mon Sep 17 00:00:00 2001 From: eli Date: Thu, 29 Oct 2026 14:27:33 -0500 Subject: [PATCH 25/32] 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 (cherry picked from commit e0c373d67187e60f248b3d4410d8efd065dc4936) --- 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 feb54881abf7665c75214bf6718c17505196d851 Mon Sep 17 00:00:00 2001 From: eli Date: Thu, 29 Oct 2026 14:27:33 -0500 Subject: [PATCH 26/32] 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 (cherry picked from commit 8cc038f509507d5d9c9da1c44bcbcdeea171c355) --- 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 d7ff37dcb63a14b12e864a293ee149b051efa20e Mon Sep 17 00:00:00 2001 From: eli Date: Thu, 29 Oct 2026 14:27:33 -0500 Subject: [PATCH 27/32] 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 (cherry picked from commit 1eea9d8ba5a3068ffae9b1210c1a5cae422dbcdf) --- 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 7a233d1bf9d4b225ac642b2dde61eb9766a37506 Mon Sep 17 00:00:00 2001 From: eli Date: Thu, 29 Oct 2026 16:18:30 -0500 Subject: [PATCH 28/32] 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 (cherry picked from commit 329436039c1585fc03f850d7934328ebf8786ca7) --- 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 d1e560d7d18ca012589ad93500b260b209ab6882 Mon Sep 17 00:00:00 2001 From: eli Date: Thu, 29 Oct 2026 16:18:30 -0500 Subject: [PATCH 29/32] 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 (cherry picked from commit d2d1f869065981a5ce481bc31ecb844925659ef2) --- 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 ecc6491f1f23d853c9bb6a4a926faae46ce27347 Mon Sep 17 00:00:00 2001 From: eli Date: Fri, 30 Oct 2026 08:38:51 -0500 Subject: [PATCH 30/32] 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 03ed3f01105e7840cfc8afbb7bda02bf6a5b6c37 Mon Sep 17 00:00:00 2001 From: Zeev Manilovich Date: Fri, 30 Oct 2026 16:36:19 +0200 Subject: [PATCH 31/32] 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 0a547e5afed8a30b455740510409e9083d6cfcf2 Mon Sep 17 00:00:00 2001 From: Zeev Manilovich Date: Fri, 30 Oct 2026 16:45:11 +0200 Subject: [PATCH 32/32] 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.