diff --git a/README.md b/README.md index e249ce14..01e3ed49 100644 --- a/README.md +++ b/README.md @@ -40,6 +40,38 @@ calls into the SDK against its type annotations. No pydantic mypy plugin is need - The blocking client, `permit.sync.Permit`, is typed as blocking: `permit.api.users.get("user")` returns a `UserRead`, not a coroutine. +## Logging + +The SDK logs with [loguru](https://github.com/Delgan/loguru) and logs nothing unless you +enable it in the `log` option: + +```py +permit = Permit(token="", log={"enable": True, "level": "debug"}) +``` + +- The SDK adds no loguru sink of its own. Its records go to the sinks your application has + added, or to loguru's default stderr sink, in the format of those sinks. +- `"enable": False` (the default) calls loguru's `logger.disable("permit")`. `"enable": True` + undoes that call, with `logger.enable("permit")`, only if an earlier client made it, so a + `logger.disable()` your application made for `permit` or one of its modules still + applies. When it does undo it, loguru also drops any `permit.*` module disable made since. +- `level` (default `"info"`) is the lowest severity the SDK logs. Its records below it never + reach a sink. Your application's own records are not affected. The SDK logs its HTTP + requests and the PDP's responses at `"debug"`. With `"enable": True`, for a level name + loguru does not know, the SDK logs a warning that names it and uses `"info"`. +- `label` (default `"Permit"`) is put in square brackets before every message the SDK logs. +- `json` is not applied. For JSON output, give your application a serialized sink in place + of loguru's default one: `logger.remove()`, then `logger.add(sys.stderr, serialize=True)`. + Added next to the default sink, it prints every record a second time. +- loguru's logger is process-wide, so these settings are too: the client created last + decides whether the SDK logs, and the last one created with `"enable": True` decides the + level and the label, for every client in the process. `wait_for_sync()` creates no + client: it yields a copy of the client it is called on. +- The SDK replaces the API key of every client in the process with `[REDACTED]` in the + messages it logs and in the PDP error bodies it puts in a `PermitConnectionError`, so a + PDP that echoes the key back does not expose it. A user name and password written into + the `api_url` or `pdp` URL are not replaced: the SDK logs its request URLs at `"debug"`. + ## Deprecations A future major release, permit 4.0, will remove the following. They still work in 3.x, and diff --git a/permit/api/base.py b/permit/api/base.py index def26a01..ea404d50 100644 --- a/permit/api/base.py +++ b/permit/api/base.py @@ -2,10 +2,10 @@ import aiohttp from aiohttp import ClientTimeout -from loguru import logger from permit.api.encoders import jsonable_encoder from permit.utils.pydantic_version import PYDANTIC_VERSION +from permit.utils.sdk_logger import sdk_logger if TYPE_CHECKING: # The v1 API is what runs under either pydantic major, so type-check against it. @@ -68,10 +68,10 @@ def __init__( self._client_config["timeout"] = ClientTimeout(total=timeout) def _log_request(self, url: str, method: str) -> None: - logger.debug(f"Sending HTTP request: {method} {url}") + sdk_logger.debug(f"Sending HTTP request: {method} {url}") def _log_response(self, url: str, method: str, status: int) -> None: - logger.debug(f"Received HTTP response: {method} {url}, status: {status}") + sdk_logger.debug(f"Received HTTP response: {method} {url}, status: {status}") def _prepare_json( self, json: BaseModel | dict[str, Any] | list[Any] | None = None @@ -241,7 +241,7 @@ def _build_http_client( async def _set_context_from_api_key(self) -> None: """Set the API context and permitted access level based on the API key scope.""" - logger.debug("Fetching api key scope") + sdk_logger.debug("Fetching api key scope") scope = await self.__api_keys.get("/scope", model=APIKeyScopeRead) if scope.organization_id is not None: diff --git a/permit/api/context.py b/permit/api/context.py index 9d72d835..72d3b5df 100644 --- a/permit/api/context.py +++ b/permit/api/context.py @@ -1,8 +1,7 @@ from enum import Enum -from loguru import logger - from permit.exceptions import PermitContextChangeError +from permit.utils.sdk_logger import sdk_logger class ApiKeyAccessLevel(str, Enum): @@ -198,7 +197,7 @@ def set_organization_level_context(self, org: str) -> None: org: The organization key. """ self.__verify_can_access_org(org) - logger.debug(f"Setting organization level context: {org}") + sdk_logger.debug(f"Setting organization level context: {org}") self._context_level = ApiContextLevel.ORGANIZATION self._organization = org self._project = None @@ -212,7 +211,7 @@ def set_project_level_context(self, org: str, project: str) -> None: project: The project key. """ self.__verify_can_access_project(org, project) - logger.debug(f"Setting project level context: {org}/{project}") + sdk_logger.debug(f"Setting project level context: {org}/{project}") self._context_level = ApiContextLevel.PROJECT self._organization = org self._project = project @@ -227,7 +226,7 @@ def set_environment_level_context(self, org: str, project: str, environment: str environment: The environment key. """ self.__verify_can_access_environment(org, project, environment) - logger.debug(f"Setting environment level context: {org}/{project}/{environment}") + sdk_logger.debug(f"Setting environment level context: {org}/{project}/{environment}") self._context_level = ApiContextLevel.ENVIRONMENT self._organization = org self._project = project diff --git a/permit/config.py b/permit/config.py index 7a42f941..490c6576 100644 --- a/permit/config.py +++ b/permit/config.py @@ -13,22 +13,46 @@ class LoggerConfig(BaseModel): - """Logging settings of the SDK.""" + """Logging settings of the SDK. + + The SDK logs with loguru and adds no sink of its own: its records go to the loguru sinks + the application has added, or to loguru's default stderr sink, in the format of those + sinks. loguru's logger is process-wide, so these settings are too: the client created + last decides whether the SDK logs, and the last one created with `enable` True decides + the level and the label, for every client in the process. + + Whatever these settings, the SDK replaces the API key of every client in the process + with `[REDACTED]` in the messages it logs and in the PDP error bodies it puts in a + `PermitConnectionError`. A user name and password written into the `api_url` or `pdp` + URL are not replaced. + """ enable: bool = Field( - default=False, description="Whether or not to enable logging from the Permit library" + default=False, + description="Whether the SDK logs. False calls loguru's logger.disable('permit'), so " + "nothing is logged. True undoes that call with logger.enable('permit') if an earlier " + "client made it, and otherwise leaves loguru's switches alone, so a logger.disable() " + "the application made for 'permit' or one of its modules still applies.", ) level: str = Field( - default="info", description="Sets the log level configured for the Permit SDK Logger." + default="info", + description="The lowest severity the SDK logs, such as 'debug', 'info', 'warning' or " + "'error', in any case; 'warn' and 'fatal' are read as 'warning' and 'critical'. The SDK " + "drops its records below it before they reach any sink. " + "Read only when enable is True; for a name loguru does not know, the SDK logs a " + "warning and uses 'info'.", ) label: str = Field( default="Permit", - description="Sets the label configured for logs emitted by the Permit SDK Logger.", + description="Put in square brackets before the message of every record the SDK logs, " + "as in '[Permit] ...'. An empty string adds nothing. Read only when enable is True.", ) log_as_json: bool = Field( default=False, alias="json", - description="Sets whether the SDK log output should be in JSON format.", + description="Not applied. The format of the SDK's records is that of the loguru sinks " + "they reach. For JSON, the application replaces loguru's default sink with a " + "serialized one: logger.remove(), then logger.add(sys.stderr, serialize=True).", ) @@ -54,8 +78,11 @@ class PermitConfig(BaseModel): # A positional `...`, not `default=...`: type checkers take any `default=` # keyword as a default, so `PermitConfig()` without a token would pass them. + # repr=False keeps the key out of repr() and str() of the config, and so out of + # tracebacks that print frame values, such as loguru's with diagnose=True. token: str = Field( ..., + repr=False, description="The token (API Key) used for authorization against the PDP " "and the Permit REST API.", ) diff --git a/permit/enforcement/enforcer.py b/permit/enforcement/enforcer.py index 119a5d4e..c9d51027 100644 --- a/permit/enforcement/enforcer.py +++ b/permit/enforcement/enforcer.py @@ -5,7 +5,6 @@ import aiohttp from aiohttp import ClientTimeout -from loguru import logger from typing_extensions import NotRequired, TypedDict from permit.config import PermitConfig @@ -14,6 +13,7 @@ from permit.utils.context import Context, ContextStore from permit.utils.dicts import deep_merge from permit.utils.pydantic_version import PYDANTIC_VERSION +from permit.utils.sdk_logger import sdk_logger from permit.utils.sync import SyncClass if TYPE_CHECKING: @@ -53,7 +53,15 @@ async def read_error_body(response: aiohttp.ClientResponse) -> str: surrounding handler and re-reported as "cannot connect to the PDP container". A 403 for a wrong API key was indistinguishable from the PDP being down, which is a genuinely misleading error to hand a user. + + Every API key the SDK knows is replaced with ``[REDACTED]``: the body goes into + the SDK's log record and into the PermitConnectionError raised to the caller, + and a PDP may echo back the key it rejected. """ + return sdk_logger.scrub(await _read_body_text(response)) + + +async def _read_body_text(response: aiohttp.ClientResponse) -> str: try: return repr(await response.json()) except (aiohttp.ClientError, ValueError): @@ -179,7 +187,7 @@ async def authorized_users( raise PermitConnectionError(msg) error_body = await read_error_body(response) - logger.error( + sdk_logger.error( "error in permit.authorized_users({}, {}):\n{}\n{}".format( action, self._resource_repr(normalized_resource), @@ -198,7 +206,7 @@ async def authorized_users( raise PermitConnectionError(msg) content: dict[str, Any] = await response.json() - logger.debug( + sdk_logger.debug( f"permit.authorized_users() response:" f"\ninput: {pformat(request_body, indent=2)}" f"\nresponse status: {response.status}" @@ -207,7 +215,7 @@ async def authorized_users( result: AuthorizedUsersResult = parse_obj_as(AuthorizedUsersResult, content) return result except aiohttp.ClientError as err: - logger.error( + sdk_logger.error( f"error in permit.authorized_users({action}, " f"{self._resource_repr(normalized_resource)}):\n{err}" ) @@ -314,10 +322,10 @@ async def bulk_check( f"status code: {response.status}", error_body, ) - logger.error(msg) + sdk_logger.error(msg) raise PermitConnectionError(msg) content: dict[str, Any] = await response.json() - logger.debug( + sdk_logger.debug( f"permit.check() response:\n" f"input: {pformat(request_body, indent=2)}\n" f"response status: {response.status}\n" @@ -339,7 +347,7 @@ async def bulk_check( ), err, ) - logger.error(msg) + sdk_logger.error(msg) raise PermitConnectionError(msg, error=err) from err return decisions @@ -416,7 +424,7 @@ async def check( raise PermitConnectionError(msg) error_body = await read_error_body(response) - logger.error( + sdk_logger.error( "error in permit.check({}, {}, {}):\n{}\n{}".format( normalized_user, action, @@ -436,7 +444,7 @@ async def check( raise PermitConnectionError(msg) content: dict[str, Any] = await response.json() - logger.debug( + sdk_logger.debug( f"permit.check() response:\n" f"body: {pformat(body, indent=2)}\n" f"response status: {response.status}\n" @@ -445,7 +453,7 @@ async def check( decision: bool = bool(content.get("allow", False)) return decision except aiohttp.ClientError as err: - logger.error( + sdk_logger.error( f"error in permit.check({normalized_user}, {action}, " f"{self._resource_repr(normalized_resource)}):" f"\n{err}" @@ -514,7 +522,7 @@ async def get_user_permissions( else content ) - logger.debug( + sdk_logger.debug( f"permit.get_user_permissions() response:\n" f"input: {pformat(input_data, indent=2)}\n" f"response data: {pformat(permissions, indent=2)}" @@ -522,7 +530,7 @@ async def get_user_permissions( return permissions except aiohttp.ClientError as err: - logger.error(f"Error in permit.get_user_permissions(): {err}") + sdk_logger.error(f"Error in permit.get_user_permissions(): {err}") msg = ( f"Permit SDK got error: {err}, \n" f"and cannot connect to the PDP container, please check your configuration " diff --git a/permit/exceptions.py b/permit/exceptions.py index 5a71176e..319b1dac 100644 --- a/permit/exceptions.py +++ b/permit/exceptions.py @@ -5,10 +5,10 @@ from typing import TYPE_CHECKING, Any, TypeVar import aiohttp -from loguru import logger from typing_extensions import ParamSpec, deprecated from permit.utils.pydantic_version import PYDANTIC_VERSION +from permit.utils.sdk_logger import sdk_logger if TYPE_CHECKING: # The v1 API is what runs under either pydantic major, so type-check against it. @@ -288,7 +288,7 @@ async def wrapped(*args: P.args, **kwargs: P.kwargs) -> R: try: return await func(*args, **kwargs) except aiohttp.ClientError as err: - logger.error(f"got client error while sending an http request:\n{err}") + sdk_logger.error(f"got client error while sending an http request:\n{err}") msg = f"{err}" raise PermitConnectionError(msg, error=err) from err diff --git a/permit/logger.py b/permit/logger.py index d1677f87..48f35113 100644 --- a/permit/logger.py +++ b/permit/logger.py @@ -1,15 +1,66 @@ +import contextlib + from loguru import logger from permit.config import PermitConfig +from permit.utils.sdk_logger import PACKAGE, sdk_logger + +PERMIT_MODULE = PACKAGE -PERMIT_MODULE = "permit" +# The names Python's logging module also accepts, and the ones the Node SDK's logger uses. +_LEVEL_ALIASES = {"WARN": "WARNING", "FATAL": "CRITICAL"} def configure_logger(config: PermitConfig) -> None: - """Silence the SDK's loguru output unless the config enables logging. + """Apply the `log` settings of `config` to the SDK's log records. + + The settings are process-wide, as loguru's logger is: the client created last decides + whether the SDK logs, and the last one created with `log.enable` True decides the level + and the label, for every client. The SDK adds no sink and leaves the application's sinks + and levels alone, so its records are written wherever loguru writes the application's, + in the format of those sinks. + + - `log.enable` False calls `logger.disable("permit")`, so nothing is logged. True + undoes that call with `logger.enable("permit")` if an earlier client made it, and + otherwise leaves loguru's switches alone, so a `logger.disable` the application made + for the package or one of its modules still applies. + - `log.level` drops the SDK's records below that severity before they reach any sink. + - `log.label` is put in brackets before each message. + - `log.log_as_json` is not applied: loguru serializes per sink. For JSON output, the + application replaces loguru's default sink with a serialized one: `logger.remove()`, + then `logger.add(sys.stderr, serialize=True)`. + + Whatever the settings, the API key in `config.token` is replaced with `[REDACTED]` in + every message the SDK logs and in the PDP error bodies it puts in a + `PermitConnectionError`. + + An unknown `log.level` does not fail client creation: the SDK logs a warning that names + the value and uses INFO. Args: - config: The SDK configuration; only `config.log.enable` is read. + config: The SDK configuration. """ + sdk_logger.redact(config.token) if not config.log.enable: - logger.disable(PERMIT_MODULE) + sdk_logger.disable() + return + level_no = _level_no(config.log.level) + if level_no is None: + sdk_logger.enable(min_level_no=logger.level("INFO").no, label=config.log.label) + sdk_logger.warning( + f"Unknown log level {config.log.level!r} in the Permit SDK config (log.level), " + "so the SDK logs at INFO. Use trace, debug, info, success, warning, error or " + "critical, or a level added with loguru's logger.level()." + ) + return + sdk_logger.enable(min_level_no=level_no, label=config.log.label) + + +def _level_no(level: str) -> int | None: + upper = level.upper() + # loguru's level names are case-sensitive: try the name as given first, so a level the + # application added in lower case is found, then the upper-case name of a built-in one. + for name in (level, _LEVEL_ALIASES.get(upper, upper)): + with contextlib.suppress(ValueError): + return logger.level(name).no + return None diff --git a/permit/permit.py b/permit/permit.py index 51d6f51f..a636a05c 100644 --- a/permit/permit.py +++ b/permit/permit.py @@ -1,9 +1,8 @@ -import json +import copy from collections.abc import Generator from contextlib import contextmanager from typing import Any, Literal -from loguru import logger from typing_extensions import Self from permit.api.api_client import PermitApiClient @@ -20,6 +19,7 @@ from permit.logger import configure_logger from permit.pdp_api.pdp_api_client import PermitPdpApiClient from permit.utils.context import Context +from permit.utils.sdk_logger import sdk_logger class Permit: @@ -35,14 +35,17 @@ def __init__(self, config: PermitConfig | None = None, **options: Any) -> None: self._config: PermitConfig = config if config is not None else PermitConfig(**options) configure_logger(self._config) + self._connect() + sdk_logger.debug( + f"Permit SDK initialized: api_url={self._config.api_url}, pdp={self._config.pdp}" + ) + + def _connect(self) -> None: + """Create the clients that send this client's requests, from its config.""" self._enforcer = Enforcer(self._config) self._api = PermitApiClient(self._config) self._elements = ElementsApi(self._config) self._pdp_api = PermitPdpApiClient(self._config) - logger.debug( - "Permit SDK initialized with config:\n${}", - json.dumps(self._config.dict(exclude={"api_context"})), - ) @property def config(self) -> PermitConfig: @@ -81,7 +84,7 @@ def wait_for_sync( https://docs.permit.io/how-to/manage-data/local-facts-uploader """ if not self._config.proxy_facts_via_pdp: - logger.warning( + sdk_logger.warning( "Tried to wait for synced facts but proxy_facts_via_pdp is disabled, ignoring..." ) yield self @@ -90,7 +93,12 @@ def wait_for_sync( contextualized_config.facts_sync_timeout = timeout if policy is not None: contextualized_config.facts_sync_timeout_policy = policy - yield self.__class__(contextualized_config) + # A copy of this client that sends its requests with the new config. Creating a new + # client instead would apply its log settings to the whole process again. + waiting: Self = copy.copy(self) + waiting._config = contextualized_config + waiting._connect() + yield waiting @property def api(self) -> PermitApiClient: diff --git a/permit/sync.py b/permit/sync.py index c2e066ad..84bc0d7b 100644 --- a/permit/sync.py +++ b/permit/sync.py @@ -31,6 +31,8 @@ class Permit(AsyncPermit): def __init__(self, config: PermitConfig | None = None, **options: Any) -> None: super().__init__(config, **options) + + def _connect(self) -> None: self._enforcer = SyncEnforcer(self._config) # type: ignore[assignment] self._api = SyncPermitApiClient(self._config) # type: ignore[assignment] self._elements = SyncElementsApi(self._config) # type: ignore[assignment] diff --git a/permit/utils/sdk_logger.py b/permit/utils/sdk_logger.py new file mode 100644 index 00000000..07faed11 --- /dev/null +++ b/permit/utils/sdk_logger.py @@ -0,0 +1,114 @@ +import threading + +from loguru import logger + +REDACTED = "[REDACTED]" +# The package whose records loguru's logger.enable() and logger.disable() switch on and off. +PACKAGE = "permit" + + +class SdkLogger: + """Logs the SDK's own records to loguru's logger, applying the SDK's `log` settings. + + Each record reaches loguru from the SDK module that logged it, so + `logger.disable("permit")`, `logger.enable("permit")` and the application's sinks treat + it as a record of that module. On the way, this drops records below the minimum + severity, replaces every registered API key with `[REDACTED]` and prefixes the message + with the label. + + Its settings are process-wide, like loguru's logger. Until `enable` is called, it + keeps every record and adds no label. + """ + + def __init__(self) -> None: + self._min_level_no = 0 + self._label = "" + # Whether `disable` called logger.disable("permit") after the last `enable`. + self._disabled_package = False + self._secrets_lock = threading.Lock() + # Longest first: where one secret contains another, such as a key and a prefix of + # it, the whole of the longer one is replaced, not just the shorter part. Replaced, + # never mutated, so a thread that logs while another registers a secret reads + # either the old tuple or the new one. + self._secrets: tuple[str, ...] = () + + def disable(self) -> None: + """Stop loguru from passing on any record of the package: `logger.disable("permit")`.""" + logger.disable(PACKAGE) + self._disabled_package = True + + def enable(self, *, min_level_no: int, label: str) -> None: + """Keep the records from `min_level_no` up, with `label` before each message. + + If `disable` was called since the last `enable`, this undoes it with + `logger.enable("permit")`. Otherwise it leaves loguru's switches alone: loguru's + enable would also drop every `logger.disable` the application set for a module of + the package, and override an application-wide `logger.disable("")`. + + Args: + min_level_no: The loguru severity number below which records are dropped. + label: The text put in brackets before each message; an empty string adds none. + """ + self._min_level_no = min_level_no + self._label = label + if self._disabled_package: + logger.enable(PACKAGE) + self._disabled_package = False + + def redact(self, secret: str) -> None: + """Replace `secret` with `[REDACTED]` in every record logged from now on. + + The secret without its leading and trailing whitespace is replaced too: a key read + from a file or an environment variable may end with a space, which an HTTP server + that echoes the key back has stripped. + + Args: + secret: A credential, such as an API key. A secret that is empty or only + whitespace is ignored. + """ + trimmed = secret.strip() + if not trimmed: + return + with self._secrets_lock: + new = {secret, trimmed}.difference(self._secrets) + if new: + self._secrets = tuple(sorted((*self._secrets, *new), key=len, reverse=True)) + + def scrub(self, text: str) -> str: + """Return `text` with every registered secret replaced with `[REDACTED]`. + + Args: + text: Any text the SDK logs or puts in an exception. + + Returns: + The text without any registered secret. + """ + for secret in self._secrets: + text = text.replace(secret, REDACTED) + return text + + def debug(self, message: str) -> None: + """Log `message` with severity DEBUG.""" + self._log("DEBUG", message) + + def warning(self, message: str) -> None: + """Log `message` with severity WARNING.""" + self._log("WARNING", message) + + def error(self, message: str) -> None: + """Log `message` with severity ERROR.""" + self._log("ERROR", message) + + def _log(self, level: str, message: str) -> None: + if logger.level(level).no < self._min_level_no: + return + message = self.scrub(message) + if self._label: + message = f"[{self._label}] {message}" + # depth=2 skips this method and the one that called it, so loguru attributes the + # record to the SDK module that logged it. The message goes without arguments, so + # loguru does not call str.format on it and braces in it are kept as they are. + logger.opt(depth=2).log(level, message) + + +sdk_logger = SdkLogger() diff --git a/pyproject.toml b/pyproject.toml index d177b569..3ef409a0 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -242,6 +242,11 @@ convention = "google" [tool.ruff.lint.flake8-tidy-imports] ban-relative-imports = "all" +[tool.ruff.lint.flake8-tidy-imports.banned-api] +# A record logged straight to loguru would skip the SDK's log level and label, and the +# replacement of the API key with [REDACTED] (PER-16680). +"loguru.logger".msg = "Log through permit.utils.sdk_logger, which redacts the API key." + [tool.ruff.lint.flake8-type-checking] # pydantic evaluates field annotations at runtime, so the imports they use # must never be moved under `if TYPE_CHECKING:`. @@ -271,7 +276,10 @@ runtime-evaluated-base-classes = ["pydantic.BaseModel", "pydantic.v1.BaseModel"] "T201", # progress output for long e2e runs; pytest captures it "BLE001", # e2e tests turn any unexpected exception into a readable pytest.fail "S603", # subprocesses run the interpreter under test with the test's own arguments + "TID251", # tests add loguru sinks and log the way an application does ] +# The SDK's loguru wrapper, and the module that reads loguru's levels for log.level. +"permit/{logger,utils/sdk_logger}.py" = ["TID251"] # These are standalone CLI programs, not library code: writing the rendered # report to stdout IS their interface, so the "no print" rule does not apply. "{.github/scripts,scripts,skills/permit-python-3-migration/scripts}/*.py" = [ diff --git a/tests/test_fix_logging.py b/tests/test_fix_logging.py new file mode 100644 index 00000000..5422f424 --- /dev/null +++ b/tests/test_fix_logging.py @@ -0,0 +1,695 @@ +"""Offline tests for the SDK's logging (PER-16680). + +The SDK logs through loguru's process-wide logger and adds no sink of its own. These tests +add sinks the way an application does, and read what reached them: a text sink on stderr in +loguru's default format, read through capsys, and a serialized (JSON) sink. Every request is +served by a local pytest_httpserver. +""" + +import json +import re +import subprocess +import sys +import types +from collections.abc import Iterator +from dataclasses import dataclass, field +from pathlib import Path +from typing import Any + +import pytest +from loguru import logger +from pytest_httpserver import HTTPServer +from werkzeug import Request, Response + +from permit import Permit, PermitConfig +from permit.enforcement.enforcer import CheckQuery +from permit.exceptions import PermitConnectionError +from permit.sync import Permit as SyncPermit +from permit.utils.sdk_logger import REDACTED, SdkLogger, sdk_logger + +SENTINEL = "permit_key_SENTINEL_9f8e7d6c5b4a39281706f5e4d3c2b1a0" +ORG_ID = "00000000-0000-4000-8000-00000000000a" +PROJECT_ID = "00000000-0000-4000-8000-00000000000b" +ENV_ID = "00000000-0000-4000-8000-00000000000c" +USERS = f"/v2/facts/{PROJECT_ID}/{ENV_ID}/users" +WAIT_FOR_SYNC_WARNING = "Tried to wait for synced facts" + + +def _probe() -> None: + logger.log("TRACE", "permit logging probe") + + +def _permit_records_enabled() -> bool: + """Whether loguru lets the records of the permit package through right now. + + loguru has no getter for this, so log a TRACE record from a function whose module name + is in the package, and see whether a sink receives it. + """ + received: list[str] = [] + probe_module = "permit._logging_probe" + sink_id = logger.add( + received.append, level="TRACE", filter=lambda record: record["name"] == probe_module + ) + try: + types.FunctionType(_probe.__code__, {"__name__": probe_module, "logger": logger})() + finally: + logger.remove(sink_id) + return bool(received) + + +@pytest.fixture(autouse=True) +def isolated_logging() -> Iterator[None]: + """Start as a fresh process does, and put the SdkLogger and loguru's switches back after. + + Restoring loguru's switch for "permit" also drops any switch a test set for a module of + the package. + """ + was_enabled = _permit_records_enabled() + saved = vars(sdk_logger).copy() + vars(sdk_logger).update(vars(SdkLogger())) + logger.enable("permit") + yield + vars(sdk_logger).update(saved) + if was_enabled: + logger.enable("permit") + else: + logger.disable("permit") + + +@dataclass +class AppSinks: + """What the application's own loguru sinks received during a test.""" + + capsys: pytest.CaptureFixture[str] + json_lines: list[str] = field(default_factory=list) + _stderr: str = "" + + def stderr(self) -> str: + captured = self.capsys.readouterr() + assert captured.out == "" + self._stderr += captured.err + return self._stderr + + def everything(self) -> str: + return self.stderr() + "".join(self.json_lines) + + def records(self) -> list[dict[str, Any]]: + return [json.loads(line)["record"] for line in self.json_lines] + + def sdk_records(self) -> list[dict[str, Any]]: + return [ + record + for record in self.records() + if record["name"] == "permit" or record["name"].startswith("permit.") + ] + + def sdk_levels(self) -> set[str]: + return {record["level"]["name"] for record in self.sdk_records()} + + def wait_for_sync_warnings(self) -> list[dict[str, Any]]: + """The records of the warning `wait_for_sync` logs when facts are not proxied.""" + return [ + record for record in self.sdk_records() if WAIT_FOR_SYNC_WARNING in record["message"] + ] + + +def write_to_stderr(message: str) -> None: + """Write to the sys.stderr of the moment: capsys replaces it in each phase of a test.""" + sys.stderr.write(message) + + +@pytest.fixture +def app_sinks(capsys: pytest.CaptureFixture[str]) -> Iterator[AppSinks]: + """A stderr sink in loguru's default format and a JSON sink, both at DEBUG.""" + sinks = AppSinks(capsys) + sink_ids = [ + logger.add(write_to_stderr, level="DEBUG"), + logger.add(sinks.json_lines.append, level="DEBUG", serialize=True), + ] + yield sinks + for sink_id in sink_ids: + logger.remove(sink_id) + + +def make_config(httpserver: HTTPServer, *, token: str = SENTINEL, **log: Any) -> PermitConfig: + url = httpserver.url_for("").rstrip("/") + return PermitConfig(token=token, api_url=url, pdp=url, log=log) + + +def serve(httpserver: HTTPServer) -> None: + """Answer the requests `use_async_client` and `use_sync_client` make.""" + httpserver.expect_request("/v2/api-key/scope", method="GET").respond_with_json( + {"organization_id": ORG_ID, "project_id": PROJECT_ID, "environment_id": ENV_ID} + ) + httpserver.expect_request(USERS, method="GET").respond_with_json( + {"data": [], "total_count": 0, "page_count": 0} + ) + # Not JSON, so reading the response raises an aiohttp error, which the SDK logs. + httpserver.expect_request(f"{USERS}/user-1", method="GET").respond_with_data( + "not json", content_type="text/plain" + ) + httpserver.expect_request("/allowed", method="POST").respond_with_json({"allow": True}) + httpserver.expect_request("/allowed/bulk", method="POST").respond_with_data( + "PDP failure", status=500 + ) + + +BULK: list[CheckQuery] = [{"user": "user-1", "action": "read", "resource": "document"}] + + +async def use_async_client(permit: Permit) -> None: + """Go through every kind of record the SDK logs: DEBUG, WARNING and ERROR.""" + with permit.wait_for_sync(): + pass + assert await permit.check("user-1", "read", "document") + await permit.api.users.list() + with pytest.raises(PermitConnectionError): + await permit.api.users.get("user-1") + with pytest.raises(PermitConnectionError): + await permit.bulk_check(BULK) + + +def use_sync_client(permit: SyncPermit) -> None: + """The blocking twin of `use_async_client`.""" + with permit.wait_for_sync(): + pass + assert permit.check("user-1", "read", "document") + permit.api.users.list() + with pytest.raises(PermitConnectionError): + permit.api.users.get("user-1") + with pytest.raises(PermitConnectionError): + permit.bulk_check(BULK) + + +def assert_api_key_not_logged( + httpserver: HTTPServer, app_sinks: AppSinks, expected_levels: set[str] +) -> None: + # The key was in use: every request carried it. + sent = {request.headers.get("Authorization") for request, _ in httpserver.log} + assert sent == {f"Bearer {SENTINEL}"} + output = app_sinks.everything() + assert SENTINEL not in output + # Nothing was redacted either: no SDK record held the key in the first place. + assert REDACTED not in output + assert app_sinks.sdk_levels() == expected_levels + # Each SDK record is one line on stderr, in the sink's format. + assert app_sinks.stderr().count(" | permit.") == len(app_sinks.sdk_records()) + + +LOG_LEVELS = [ + pytest.param({"level": "debug"}, {"DEBUG", "WARNING", "ERROR"}, id="debug"), + pytest.param({"level": "info"}, {"WARNING", "ERROR"}, id="info"), + pytest.param({}, {"WARNING", "ERROR"}, id="unset"), +] +AS_JSON = [pytest.param(True, id="json"), pytest.param(False, id="text")] + + +@pytest.mark.parametrize(("log", "expected_levels"), LOG_LEVELS) +@pytest.mark.parametrize("as_json", AS_JSON) +async def test_async_client_never_logs_the_api_key( + httpserver: HTTPServer, + app_sinks: AppSinks, + log: dict[str, str], + expected_levels: set[str], + *, + as_json: bool, +) -> None: + serve(httpserver) + + await use_async_client(Permit(make_config(httpserver, enable=True, json=as_json, **log))) + + assert_api_key_not_logged(httpserver, app_sinks, expected_levels) + + +@pytest.mark.parametrize(("log", "expected_levels"), LOG_LEVELS) +@pytest.mark.parametrize("as_json", AS_JSON) +def test_sync_client_never_logs_the_api_key( + httpserver: HTTPServer, + app_sinks: AppSinks, + log: dict[str, str], + expected_levels: set[str], + *, + as_json: bool, +) -> None: + serve(httpserver) + + use_sync_client(SyncPermit(make_config(httpserver, enable=True, json=as_json, **log))) + + assert_api_key_not_logged(httpserver, app_sinks, expected_levels) + + +def echo_the_key(request: Request) -> Response: + """A PDP that rejects the request and echoes the API key it was sent.""" + return Response(f"rejected key: {request.headers['Authorization']}", status=403) + + +@pytest.mark.parametrize("enabled_by", ["config", "application"]) +async def test_an_api_key_the_pdp_echoes_back_is_redacted( + httpserver: HTTPServer, app_sinks: AppSinks, enabled_by: str +) -> None: + httpserver.expect_request("/allowed", method="POST").respond_with_handler(echo_the_key) + if enabled_by == "config": + permit = Permit(make_config(httpserver, enable=True)) + else: + # A client created with logging disabled, whose records the application turns on. + permit = Permit(make_config(httpserver)) + logger.enable("permit") + + with pytest.raises(PermitConnectionError) as raised: + await permit.check("user-1", "read", "document") + + [record] = [record for record in app_sinks.sdk_records() if record["level"]["name"] == "ERROR"] + assert f"rejected key: Bearer {REDACTED}" in record["message"] + assert SENTINEL not in app_sinks.everything() + # The application gets the body too, in the exception it may log or report. + assert f"rejected key: Bearer {REDACTED}" in str(raised.value) + assert SENTINEL not in str(raised.value) + + +async def test_errors_raised_for_a_pdp_that_echoes_the_key_do_not_hold_it( + httpserver: HTTPServer, +) -> None: + for path in ("/allowed", "/allowed/bulk", "/authorized_users"): + httpserver.expect_request(path, method="POST").respond_with_handler(echo_the_key) + permit = Permit(make_config(httpserver)) + sync_permit = SyncPermit(make_config(httpserver)) + + raised: list[PermitConnectionError] = [] + for call in ( + lambda: permit.check("user-1", "read", "document"), + lambda: permit.bulk_check(BULK), + lambda: permit.authorized_users("read", "document"), + ): + with pytest.raises(PermitConnectionError) as error: + await call() + raised.append(error.value) + with pytest.raises(PermitConnectionError) as error: + sync_permit.check("user-1", "read", "document") + raised.append(error.value) + + for error_value in raised: + assert f"rejected key: Bearer {REDACTED}" in str(error_value) + assert SENTINEL not in str(error_value) + + +async def test_a_key_is_redacted_whole_when_another_key_is_a_prefix_of_it( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + # Clients created earlier in the process with keys the real key starts with. + for length in range(len("permit_key_"), len(SENTINEL), 2): + Permit(make_config(httpserver, token=SENTINEL[:length], enable=True)) + httpserver.expect_request("/allowed", method="POST").respond_with_handler(echo_the_key) + permit = Permit(make_config(httpserver, enable=True)) + + with pytest.raises(PermitConnectionError): + await permit.check("user-1", "read", "document") + + [record] = [record for record in app_sinks.sdk_records() if record["level"]["name"] == "ERROR"] + assert record["message"].endswith(f"rejected key: Bearer {REDACTED}") + assert SENTINEL[-8:] not in app_sinks.everything() + + +async def test_a_key_with_a_trailing_space_is_redacted_when_echoed_without_it( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + httpserver.expect_request("/allowed", method="POST").respond_with_handler(echo_the_key) + permit = Permit(make_config(httpserver, token=f"{SENTINEL} ", enable=True)) + + with pytest.raises(PermitConnectionError): + await permit.check("user-1", "read", "document") + + [record] = [record for record in app_sinks.sdk_records() if record["level"]["name"] == "ERROR"] + assert record["message"].endswith(f"rejected key: Bearer {REDACTED}") + assert SENTINEL not in app_sinks.everything() + + +@pytest.mark.parametrize( + ("log", "expected_levels"), + [ + pytest.param({"level": "trace"}, {"DEBUG", "WARNING", "ERROR"}, id="trace"), + pytest.param({"level": "debug"}, {"DEBUG", "WARNING", "ERROR"}, id="debug"), + pytest.param({}, {"WARNING", "ERROR"}, id="unset"), + pytest.param({"level": "INFO"}, {"WARNING", "ERROR"}, id="INFO"), + pytest.param({"level": "warning"}, {"WARNING", "ERROR"}, id="warning"), + pytest.param({"level": "warn"}, {"WARNING", "ERROR"}, id="warn"), + pytest.param({"level": "error"}, {"ERROR"}, id="error"), + pytest.param({"level": "critical"}, set(), id="critical"), + ], +) +async def test_level_drops_the_sdk_records_below_it( + httpserver: HTTPServer, app_sinks: AppSinks, log: dict[str, str], expected_levels: set[str] +) -> None: + serve(httpserver) + + await use_async_client(Permit(make_config(httpserver, enable=True, **log))) + logger.debug("an application record") + + assert app_sinks.sdk_levels() == expected_levels + # The application's own records are not the SDK's to filter. + assert "an application record" in [record["message"] for record in app_sinks.records()] + + +async def test_an_unknown_level_warns_and_logs_at_info( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + serve(httpserver) + + await use_async_client(Permit(make_config(httpserver, enable=True, level="verbose"))) + + warnings = [ + record + for record in app_sinks.sdk_records() + if record["level"]["name"] == "WARNING" + and "Unknown log level 'verbose'" in record["message"] + ] + assert len(warnings) == 1 + assert "logs at INFO" in warnings[0]["message"] + # The same records as with level "info": no DEBUG ones. + assert app_sinks.sdk_levels() == {"WARNING", "ERROR"} + + +def test_the_traceback_of_a_failed_client_creation_hides_the_api_key( + httpserver: HTTPServer, monkeypatch: pytest.MonkeyPatch +) -> None: + def fail(**_: object) -> None: + msg = "the SDK could not configure its logger" + raise RuntimeError(msg) + + monkeypatch.setattr("permit.logger.sdk_logger.enable", fail) + lines: list[str] = [] + # diagnose=True, loguru's default, prints the value of each name on every line of the + # traceback, and the SDK's frames pass the config around. + sink_id = logger.add(lines.append, diagnose=True, backtrace=True) + config = make_config(httpserver, enable=True) + try: + try: + SyncPermit(config) + except RuntimeError: + logger.exception("the application could not start") + finally: + logger.remove(sink_id) + + output = "".join(lines) + assert "configure_logger(" in output + assert "PermitConfig(pdp=" in output + assert SENTINEL not in output + assert SENTINEL not in str(config) + + +# loguru cannot remove a level once added, so this application runs in its own process. +CUSTOM_LEVEL_APP = f""" +import sys + +from loguru import logger + +from permit import PermitConnectionError +from permit.sync import Permit + +logger.remove() +logger.add(sys.stdout, serialize=True) +logger.level("audit", no=35) +url = sys.argv[1] +permit = Permit( + token="{SENTINEL}", api_url=url, pdp=url, log={{"enable": True, "level": "audit"}} +) +with permit.wait_for_sync(): + pass +try: + permit.check("user-1", "read", "document") +except PermitConnectionError: + pass +""" + + +def test_level_accepts_a_level_the_application_added( + httpserver: HTTPServer, tmp_path: Path +) -> None: + httpserver.expect_request("/allowed", method="POST").respond_with_data( + "PDP failure", status=500 + ) + app = tmp_path / "app.py" + app.write_text(CUSTOM_LEVEL_APP) + + result = subprocess.run( + [sys.executable, str(app), httpserver.url_for("").rstrip("/")], + capture_output=True, + text=True, + timeout=120, + check=False, + ) + + assert result.returncode == 0, result.stderr + # "audit" (35) sits between WARNING (30) and ERROR (40): only the ERROR record is kept. + [record] = [json.loads(line)["record"] for line in result.stdout.splitlines()] + assert record["level"]["name"] == "ERROR" + assert record["message"].startswith("[Permit] error in permit.check(") + assert SENTINEL not in result.stdout + result.stderr + + +@pytest.mark.parametrize( + ("log", "prefix"), + [ + pytest.param({}, "[Permit] ", id="default"), + pytest.param({"label": "acme-authz"}, "[acme-authz] ", id="custom"), + ], +) +async def test_label_prefixes_every_sdk_message( + httpserver: HTTPServer, app_sinks: AppSinks, log: dict[str, str], prefix: str +) -> None: + serve(httpserver) + + await use_async_client(Permit(make_config(httpserver, enable=True, level="debug", **log))) + + messages = [record["message"] for record in app_sinks.sdk_records()] + assert len(messages) > 3 + assert [message for message in messages if not message.startswith(prefix)] == [] + assert f"{prefix}{WAIT_FOR_SYNC_WARNING}" in app_sinks.stderr() + + +def test_an_empty_label_adds_no_prefix(httpserver: HTTPServer, app_sinks: AppSinks) -> None: + with SyncPermit(make_config(httpserver, enable=True, label="")).wait_for_sync(): + pass + + [record] = app_sinks.wait_for_sync_warnings() + assert record["message"].startswith(WAIT_FOR_SYNC_WARNING) + + +@pytest.mark.parametrize("token", ["", " "]) +def test_an_empty_api_key_redacts_nothing( + httpserver: HTTPServer, app_sinks: AppSinks, token: str +) -> None: + with SyncPermit(make_config(httpserver, token=token, enable=True)).wait_for_sync(): + pass + + [record] = app_sinks.wait_for_sync_warnings() + assert ( + record["message"] + == f"[Permit] {WAIT_FOR_SYNC_WARNING} but proxy_facts_via_pdp is disabled, ignoring..." + ) + + +def test_records_name_the_sdk_module_that_logged_them( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + with SyncPermit(make_config(httpserver, enable=True)).wait_for_sync(): + pass + + [record] = app_sinks.wait_for_sync_warnings() + assert (record["name"], record["function"]) == ("permit.permit", "wait_for_sync") + assert "| permit.permit:wait_for_sync:" in app_sinks.stderr() + + +@pytest.mark.parametrize("as_json", AS_JSON) +def test_log_as_json_leaves_the_format_to_the_application_sinks( + httpserver: HTTPServer, app_sinks: AppSinks, *, as_json: bool +) -> None: + with SyncPermit(make_config(httpserver, enable=True, json=as_json)).wait_for_sync(): + pass + + # One text line in the stderr sink and one JSON line in the JSON sink: the SDK + # neither adds a JSON sink of its own nor changes the application's. + [line] = [line for line in app_sinks.stderr().splitlines() if WAIT_FOR_SYNC_WARNING in line] + assert "| WARNING | permit.permit:wait_for_sync:" in line + assert len(app_sinks.wait_for_sync_warnings()) == 1 + + +DISABLED = [ + pytest.param({}, id="unset"), + pytest.param({"enable": False}, id="false"), + pytest.param( + {"enable": False, "level": "debug", "label": "x", "json": True}, id="false-with-options" + ), + pytest.param({"enable": False, "level": "not-a-level"}, id="false-unknown-level"), +] + + +@pytest.mark.parametrize("log", DISABLED) +async def test_async_client_with_logging_disabled_logs_nothing( + httpserver: HTTPServer, app_sinks: AppSinks, log: dict[str, Any] +) -> None: + serve(httpserver) + + await use_async_client(Permit(make_config(httpserver, **log))) + + assert app_sinks.everything() == "" + + +@pytest.mark.parametrize("log", DISABLED) +def test_sync_client_with_logging_disabled_logs_nothing( + httpserver: HTTPServer, app_sinks: AppSinks, log: dict[str, Any] +) -> None: + serve(httpserver) + + use_sync_client(SyncPermit(make_config(httpserver, **log))) + + assert app_sinks.everything() == "" + + +def test_the_client_created_last_decides_whether_the_sdk_logs( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + SyncPermit(make_config(httpserver)) + enabled = SyncPermit(make_config(httpserver, enable=True)) + with enabled.wait_for_sync(): + pass + assert len(app_sinks.wait_for_sync_warnings()) == 1 + + SyncPermit(make_config(httpserver)) + with enabled.wait_for_sync(): + pass + assert len(app_sinks.wait_for_sync_warnings()) == 1 + + +def test_an_enabled_client_keeps_a_disable_the_application_set_for_an_sdk_module( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + httpserver.expect_request("/allowed", method="POST").respond_with_json({"allow": True}) + logger.disable("permit.enforcement") + + permit = SyncPermit(make_config(httpserver, enable=True, level="debug")) + assert permit.check("user-1", "read", "document") + + modules = {record["name"] for record in app_sinks.sdk_records()} + assert "permit.permit" in modules + assert [module for module in modules if module.startswith("permit.enforcement")] == [] + + +def test_an_enabled_client_keeps_a_disable_the_application_set_for_the_sdk( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + logger.disable("permit") + + with SyncPermit(make_config(httpserver, enable=True)).wait_for_sync(): + pass + + assert app_sinks.sdk_records() == [] + + +def proxied_config(httpserver: HTTPServer, **log: Any) -> PermitConfig: + """A config that writes facts through the PDP, so `wait_for_sync` derives a client.""" + config = make_config(httpserver, **log) + config.proxy_facts_via_pdp = True + return config + + +def test_wait_for_sync_keeps_logging_off_after_a_disabled_client( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + proxied = SyncPermit(proxied_config(httpserver, enable=True)) + unproxied = SyncPermit(make_config(httpserver, enable=True)) + SyncPermit(make_config(httpserver)) + + with proxied.wait_for_sync(): + pass + with unproxied.wait_for_sync(): + pass + + assert app_sinks.sdk_records() == [] + + +def test_wait_for_sync_keeps_the_level_and_label_of_the_client_created_last( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + proxied = SyncPermit(proxied_config(httpserver, enable=True, level="debug", label="first")) + last = SyncPermit(make_config(httpserver, enable=True, level="warning", label="last")) + records_before = len(app_sinks.sdk_records()) + + with proxied.wait_for_sync(): + pass + with last.wait_for_sync(): + pass + + [record] = app_sinks.sdk_records()[records_before:] + assert record["message"].startswith(f"[last] {WAIT_FOR_SYNC_WARNING}") + + +@pytest.mark.parametrize( + "client_class", [pytest.param(Permit, id="async"), pytest.param(SyncPermit, id="sync")] +) +async def test_wait_for_sync_yields_a_client_that_waits_for_the_facts( + httpserver: HTTPServer, client_class: type[Permit] +) -> None: + serve(httpserver) + httpserver.expect_request(re.compile(r"/facts/tenants/.*"), method="DELETE").respond_with_data( + "", status=204 + ) + permit = client_class(proxied_config(httpserver)) + + with permit.wait_for_sync(timeout=3.0, policy="fail") as waiting: + assert type(waiting) is client_class + assert waiting.config.facts_sync_timeout == 3.0 + deleted = waiting.api.tenants.delete("tenant-1") + if client_class is Permit: + await deleted + deleted = permit.api.tenants.delete("tenant-2") + if client_class is Permit: + await deleted + + [waited, not_waited] = [ + request for request, _ in httpserver.log if request.path.startswith("/facts/") + ] + assert waited.path == "/facts/tenants/tenant-1" + assert (waited.headers.get("X-Wait-Timeout"), waited.headers.get("X-Timeout-Policy")) == ( + "3.0", + "fail", + ) + assert "X-Wait-Timeout" not in not_waited.headers + assert permit.config.facts_sync_timeout is None + + +def test_the_application_can_still_turn_the_sdk_records_on_itself( + httpserver: HTTPServer, app_sinks: AppSinks +) -> None: + httpserver.expect_request("/allowed", method="POST").respond_with_json({"allow": True}) + permit = SyncPermit(make_config(httpserver)) + + logger.enable("permit") + assert permit.check("user-1", "read", "document") + + # No client enabled logging, so no level or label applies: the records are as before. + [record] = app_sinks.sdk_records() + assert record["level"]["name"] == "DEBUG" + assert record["message"].startswith("permit.check() response:") + + +def _next_handler_id() -> int: + """The id loguru gives the next sink: each `logger.add` takes the next one.""" + sink_id = logger.add(lambda _: None) + logger.remove(sink_id) + return sink_id + + +def test_creating_many_clients_adds_no_sinks(httpserver: HTTPServer, app_sinks: AppSinks) -> None: + first_free_id = _next_handler_id() + + clients = [ + client_class(make_config(httpserver, enable=True, json=True, label=f"client-{index}")) + for index in range(20) + for client_class in (Permit, SyncPermit) + ] + + assert _next_handler_id() == first_free_id + 1 + with clients[-1].wait_for_sync(): + pass + assert len(app_sinks.wait_for_sync_warnings()) == 1 + assert app_sinks.stderr().count(WAIT_FOR_SYNC_WARNING) == 1