From 59a149b45dcd10fb5a995b224ad9dca413157537 Mon Sep 17 00:00:00 2001 From: Peter Sprygada Date: Thu, 19 Mar 2026 21:17:38 -0400 Subject: [PATCH] feat: add named loggers, logger reset, and managed prefix registry - Add get_logger(name) to return named child loggers under the ipsdk namespace, with ValueError guard against double-prefixing - Add reset_logger(name) to strip handlers, reset level to NOTSET, and restore propagation on any stdlib logger by name - Add register_logger_prefix(prefix) to extend the managed-logger registry beyond the hardcoded ipsdk/httpx prefixes - Extend set_level() and initialize() with optional loggers parameter for one-shot per-call management without registry persistence - Add OpenSpec change artifacts (proposal, design, specs, tasks) for the logging enhancements --- .../.openspec.yaml | 2 + .../design.md | 79 +++++++ .../proposal.md | 31 +++ .../specs/dependency-logger-reset/spec.md | 36 +++ .../specs/managed-logger-registry/spec.md | 50 +++++ .../specs/named-loggers/spec.md | 38 ++++ .../tasks.md | 37 ++++ .../specs/dependency-logger-reset/spec.md | 36 +++ .../specs/managed-logger-registry/spec.md | 50 +++++ openspec/specs/named-loggers/spec.md | 38 ++++ src/ipsdk/logging.py | 164 +++++++++++++- tests/test_logging.py | 205 ++++++++++++++++++ 12 files changed, 755 insertions(+), 11 deletions(-) create mode 100644 openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/.openspec.yaml create mode 100644 openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/design.md create mode 100644 openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/proposal.md create mode 100644 openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/specs/dependency-logger-reset/spec.md create mode 100644 openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/specs/managed-logger-registry/spec.md create mode 100644 openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/specs/named-loggers/spec.md create mode 100644 openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/tasks.md create mode 100644 openspec/specs/dependency-logger-reset/spec.md create mode 100644 openspec/specs/managed-logger-registry/spec.md create mode 100644 openspec/specs/named-loggers/spec.md diff --git a/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/.openspec.yaml b/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/.openspec.yaml new file mode 100644 index 0000000..d8b0ed0 --- /dev/null +++ b/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/.openspec.yaml @@ -0,0 +1,2 @@ +schema: spec-driven +created: 2026-03-20 diff --git a/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/design.md b/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/design.md new file mode 100644 index 0000000..5a91f4c --- /dev/null +++ b/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/design.md @@ -0,0 +1,79 @@ +## Context + +`ipsdk.logging` wraps Python's stdlib `logging` module to provide custom levels (TRACE, FATAL, NONE), PII redaction, and a `@trace` decorator. The entire logging hierarchy is pinned to the `ipsdk` root logger; `_get_loggers()` discovers loggers only under the `("ipsdk", "httpx")` prefix tuple and caches the result. + +Downstream libraries that embed ipsdk currently have two bad options: (1) bypass `ipsdk.logging` entirely and use stdlib `logging` directly, losing PII filtering and level integration; or (2) manually manipulate stdlib logger internals. Neither is acceptable for a library that advertises itself as production-ready. + +The change is entirely within `src/ipsdk/logging.py` and `tests/test_logging.py`. No new runtime dependencies. No public API removals. + +## Goals / Non-Goals + +**Goals:** +- `get_logger(name)` returns a named child logger under the `ipsdk` namespace, or the root `ipsdk` logger when `name` is `None` (existing behaviour preserved). +- `reset_logger(name)` strips handlers and restores `propagate=True` on any arbitrary stdlib logger by name, enabling callers to silence or re-route third-party noise without touching stdlib internals. +- A module-level `_extra_logger_prefixes: set[str]` registry lets callers register additional prefixes (e.g., `"httpcore"`) so that `_get_loggers()`, `set_level()`, and `initialize()` automatically manage those loggers alongside `ipsdk.*` and `httpx`. +- `set_level()` and `initialize()` accept an optional `loggers: list[str] | None` parameter that temporarily adds prefixes for a single call (without persisting them to the registry). +- 100 % test coverage on all new paths. + +**Non-Goals:** +- Structured/JSON log formatting. +- Per-logger PII filtering rules (filtering is global). +- Hierarchical log level inheritance beyond what stdlib already provides. +- Any changes to `heuristics.py`, `connection.py`, or other modules. + +## Decisions + +### 1. `get_logger(name)` returns a child under `ipsdk.*` + +**Decision**: `get_logger("mylib")` returns `logging.getLogger("ipsdk.mylib")`, not `logging.getLogger("mylib")`. + +**Why**: Keeps the entire managed hierarchy under one root. A caller can do `ipsdk.logging.set_level(DEBUG)` and have it apply to all child loggers automatically via stdlib propagation, without needing to enumerate them. + +**Alternative considered**: Allow arbitrary logger names (callers pass `"mylib.foo"` and get exactly that logger). Rejected because it breaks the single-root invariant and makes `_get_loggers()` non-deterministic. + +### 2. `_extra_logger_prefixes` as a module-level `set` + +**Decision**: A module-level `_extra_logger_prefixes: set[str]` stores additional prefixes. A public `register_logger_prefix(prefix: str)` function adds to it. `_get_loggers()` merges `{metadata.name, "httpx"}` with this set at call time. + +**Why**: Simple, low-overhead, and thread-safe enough for startup-time registration (no hot-path writes). Avoids a full registry class for what is essentially a small config set. + +**Alternative considered**: Accept `extra_prefixes` on `set_level()` / `initialize()` only (no persistent registry). Rejected because callers would have to pass the same list on every call. + +### 3. `reset_logger(name)` operates on exact logger name, not prefix + +**Decision**: `reset_logger("httpcore")` affects only the logger named `"httpcore"`, not `"httpcore.asyncio"` etc. + +**Why**: Surgical control is safer. If a caller wants to reset a whole sub-tree, they call `reset_logger` for each. Prefix-matching would silently affect loggers the caller didn't intend. + +**Alternative considered**: Accept a prefix and reset all matching loggers. Rejected — too broad, hard to reason about in library code. + +### 4. `@cache` on `_get_loggers()` is retained but always cleared before use + +**Decision**: Keep `@cache` on `_get_loggers()` for performance; all public functions that depend on it call `_get_loggers.cache_clear()` before calling `_get_loggers()`. This is already the pattern in `set_level()` and `initialize()`. + +**Why**: Loggers are created lazily; without clearing the cache, newly registered child loggers would be missed. Clearing before use is cheap (O(1)) and safe. + +## Risks / Trade-offs + +- **`get_logger("ipsdk")` and `get_logger(None)` return the same object** — callers who pass the literal string `"ipsdk"` get a child named `"ipsdk.ipsdk"`. Document clearly that `name` should not include the `ipsdk.` prefix. This is a footgun but acceptable given the API is additive and opt-in. + → Mitigation: docstring example + `ValueError` if `name` starts with `metadata.name + "."`. + +- **`reset_logger` on an unknown name is a no-op** — stdlib `logging.getLogger("unknown")` creates a placeholder logger. Resetting it is harmless but may confuse callers who misspell a name. + → Mitigation: function returns `bool` indicating whether the logger had any handlers or non-default state before the reset. + +- **`_extra_logger_prefixes` is not thread-safe for concurrent writes** — registration is expected at import/startup time, not during live request handling. + → Mitigation: document the startup-only contract; add a `threading.Lock` around writes to be safe. + +## Migration Plan + +All changes are backwards compatible: +1. `get_logger()` with no arguments: unchanged behaviour. +2. `set_level(lvl)` with no `loggers` argument: unchanged behaviour. +3. `initialize()` with no arguments: unchanged behaviour. + +No migration steps required. Ship as a minor version bump (0.8.x → 0.9.0 since it adds public API surface). + +## Open Questions + +- Should `register_logger_prefix` be idempotent (silently ignore duplicates) or raise on duplicate? Lean toward idempotent. +- Should the `loggers` parameter on `set_level()` / `initialize()` persist to `_extra_logger_prefixes`, or be one-shot? Current decision: one-shot (non-persisting). Revisit if callers find it inconvenient. diff --git a/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/proposal.md b/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/proposal.md new file mode 100644 index 0000000..8e6bdde --- /dev/null +++ b/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/proposal.md @@ -0,0 +1,31 @@ +## Why + +The `ipsdk` logging module currently hardcodes its logger hierarchy under the `ipsdk` namespace and `_get_loggers()` only discovers `ipsdk.*` and `httpx` loggers — making it impossible for downstream libraries or application code to create named child loggers, or to suppress/reset noise from arbitrary third-party dependencies (e.g., `httpcore`, `urllib3`, `boto3`) without reaching into stdlib `logging` directly. Libraries that embed ipsdk need a first-class API to integrate their own named loggers into ipsdk's level/filter/handler management. + +## What Changes + +- Add `get_logger(name: str | None = None)` — when `name` is provided, returns a named child logger under the `ipsdk` namespace (e.g., `ipsdk.mylib`); when `None`, returns the root `ipsdk` logger (existing behaviour). +- Add `reset_logger(name: str)` — removes all handlers, resets level, and sets `propagate=True` on any arbitrary logger by name (e.g., `"httpcore"`, `"boto3"`), letting it fall through to Python's root handler or be silenced. +- Extend `set_level()` / `initialize()` to accept an optional `loggers: list[str] | None` parameter so callers can bring additional named loggers under ipsdk management without touching `propagate` internals directly. +- Update `_get_loggers()` to honour a configurable registry of extra logger names/prefixes, not just the hardcoded `("ipsdk", "httpx")` tuple. + +## Capabilities + +### New Capabilities + +- `named-loggers`: Create and retrieve named child loggers under the `ipsdk` hierarchy via `get_logger(name)`. +- `dependency-logger-reset`: Reset (clear handlers, restore propagation) arbitrary third-party loggers by name via `reset_logger(name)`. +- `managed-logger-registry`: A configurable registry of extra logger prefixes that `_get_loggers()`, `set_level()`, and `initialize()` operate on, replacing the hardcoded `("ipsdk", "httpx")` tuple. + +### Modified Capabilities + + + +## Impact + +- `src/ipsdk/logging.py`: All changes are contained here. +- `get_logger()` signature changes (adds optional `name` parameter) — backwards compatible; existing callers with no argument continue to work. +- `set_level()` and `initialize()` gain optional `loggers` parameter — backwards compatible. +- `_get_loggers()` internal logic changes; its `@cache` is still cleared on each `set_level`/`initialize` call. +- Tests: `tests/test_logging.py` will need new coverage for all three new capabilities. +- No new runtime dependencies. diff --git a/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/specs/dependency-logger-reset/spec.md b/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/specs/dependency-logger-reset/spec.md new file mode 100644 index 0000000..9609e34 --- /dev/null +++ b/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/specs/dependency-logger-reset/spec.md @@ -0,0 +1,36 @@ +## ADDED Requirements + +### Requirement: reset_logger clears handlers and restores propagation on any named logger +`ipsdk.logging.reset_logger(name)` SHALL remove all handlers from the named stdlib logger, reset its level to `NOTSET`, and set `propagate=True`, regardless of whether the logger is in the ipsdk namespace. + +#### Scenario: Reset a third-party logger +- **WHEN** `reset_logger("httpcore")` is called +- **THEN** `logging.getLogger("httpcore")` has no handlers +- **AND** its level is `logging.NOTSET` +- **AND** its `propagate` attribute is `True` + +#### Scenario: Reset an ipsdk child logger +- **WHEN** a child logger `"ipsdk.mylib"` has been configured with handlers and a level +- **AND** `reset_logger("ipsdk.mylib")` is called +- **THEN** `logging.getLogger("ipsdk.mylib")` has no handlers and level `NOTSET` + +### Requirement: reset_logger returns True if the logger had non-default state +`reset_logger` SHALL return `True` if the logger had at least one handler OR a non-NOTSET level before the reset, and `False` otherwise. + +#### Scenario: Logger had handlers +- **WHEN** `logging.getLogger("httpcore")` has one or more handlers attached +- **AND** `reset_logger("httpcore")` is called +- **THEN** the return value is `True` + +#### Scenario: Logger had no handlers or level +- **WHEN** `logging.getLogger("unknown.lib")` has no handlers and level `NOTSET` +- **AND** `reset_logger("unknown.lib")` is called +- **THEN** the return value is `False` + +### Requirement: reset_logger closes handlers before removing them +`reset_logger` SHALL call `handler.close()` on each handler before removing it, consistent with how `initialize()` manages handlers. + +#### Scenario: Handler is closed +- **WHEN** a logger has a `StreamHandler` attached +- **AND** `reset_logger` is called +- **THEN** the handler's `close()` method is called exactly once before it is removed diff --git a/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/specs/managed-logger-registry/spec.md b/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/specs/managed-logger-registry/spec.md new file mode 100644 index 0000000..8873a3c --- /dev/null +++ b/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/specs/managed-logger-registry/spec.md @@ -0,0 +1,50 @@ +## ADDED Requirements + +### Requirement: register_logger_prefix adds a prefix to the managed logger registry +`ipsdk.logging.register_logger_prefix(prefix)` SHALL add the given string to the module-level `_extra_logger_prefixes` set so that subsequent calls to `_get_loggers()`, `set_level()`, and `initialize()` include loggers whose names start with that prefix. + +#### Scenario: Registered prefix is included in logger discovery +- **WHEN** `register_logger_prefix("httpcore")` is called +- **AND** `_get_loggers()` is called (with cache cleared) +- **THEN** any existing logger named `"httpcore"` or `"httpcore.*"` is included in the returned set + +#### Scenario: Duplicate registration is idempotent +- **WHEN** `register_logger_prefix("httpcore")` is called twice +- **THEN** `_extra_logger_prefixes` contains `"httpcore"` exactly once + +### Requirement: _get_loggers includes extra prefixes from the registry +`_get_loggers()` SHALL discover loggers matching `metadata.name`, `"httpx"`, AND every prefix in `_extra_logger_prefixes`. + +#### Scenario: Default discovery without extra prefixes +- **WHEN** `_extra_logger_prefixes` is empty +- **THEN** `_get_loggers()` returns only loggers whose names start with `"ipsdk"` or `"httpx"` + +#### Scenario: Discovery with extra prefix registered +- **WHEN** `register_logger_prefix("mylib")` has been called +- **AND** `logging.getLogger("mylib.core")` exists in the logging manager +- **THEN** `_get_loggers()` includes the `"mylib.core"` logger + +### Requirement: set_level accepts an optional loggers parameter for one-shot management +`set_level(lvl, *, propagate=False, loggers=None)` SHALL accept an optional `loggers: list[str] | None` parameter. When provided, the named loggers SHALL have their level set to `lvl` in addition to the normal managed set. The extra names SHALL NOT be persisted to `_extra_logger_prefixes`. + +#### Scenario: One-shot logger level set +- **WHEN** `set_level(DEBUG, loggers=["boto3"])` is called +- **THEN** `logging.getLogger("boto3").level` is `DEBUG` +- **AND** `"boto3"` is NOT in `_extra_logger_prefixes` after the call + +### Requirement: initialize accepts an optional loggers parameter for one-shot initialization +`initialize(loggers=None)` SHALL accept an optional `loggers: list[str] | None` parameter. When provided, the named loggers SHALL be reset (handlers cleared, level set to NONE) in addition to the normally managed set. The extra names SHALL NOT be persisted to `_extra_logger_prefixes`. + +#### Scenario: One-shot logger initialization +- **WHEN** `initialize(loggers=["urllib3"])` is called +- **THEN** `logging.getLogger("urllib3")` has a single `StreamHandler` pointing to `stderr` +- **AND** its level is `NONE` +- **AND** `"urllib3"` is NOT in `_extra_logger_prefixes` after the call + +### Requirement: registry writes are thread-safe +`register_logger_prefix` SHALL use the existing `_logger_cache_lock` (or an equivalent lock) to protect writes to `_extra_logger_prefixes`. + +#### Scenario: Concurrent registration +- **WHEN** multiple threads call `register_logger_prefix` concurrently with different prefixes +- **THEN** all prefixes are present in `_extra_logger_prefixes` after all threads complete +- **AND** no `RuntimeError` or data corruption occurs diff --git a/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/specs/named-loggers/spec.md b/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/specs/named-loggers/spec.md new file mode 100644 index 0000000..7d0d9e0 --- /dev/null +++ b/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/specs/named-loggers/spec.md @@ -0,0 +1,38 @@ +## ADDED Requirements + +### Requirement: get_logger returns root logger when name is None +`ipsdk.logging.get_logger()` and `ipsdk.logging.get_logger(None)` SHALL both return the `logging.Logger` instance registered under the `ipsdk` root name, preserving existing behaviour. + +#### Scenario: Call with no argument +- **WHEN** `get_logger()` is called with no arguments +- **THEN** the returned logger's name is `"ipsdk"` + +#### Scenario: Call with None +- **WHEN** `get_logger(None)` is called +- **THEN** the returned logger's name is `"ipsdk"` + +### Requirement: get_logger returns named child logger under ipsdk namespace +When a non-None `name` is passed, `get_logger(name)` SHALL return a `logging.Logger` whose full name is `"ipsdk."`. + +#### Scenario: Named child logger +- **WHEN** `get_logger("mylib")` is called +- **THEN** the returned logger's name is `"ipsdk.mylib"` + +#### Scenario: Same instance on repeated calls +- **WHEN** `get_logger("mylib")` is called twice +- **THEN** both calls return the identical `Logger` object (stdlib behaviour via `logging.getLogger`) + +### Requirement: get_logger rejects names that already include the ipsdk prefix +If `name` starts with `"ipsdk."`, `get_logger` SHALL raise `ValueError` to prevent double-prefixing (e.g., `"ipsdk.ipsdk.mylib"`). + +#### Scenario: Prefix already present +- **WHEN** `get_logger("ipsdk.mylib")` is called +- **THEN** `ValueError` is raised with a message indicating the prefix must not be included + +### Requirement: Named child loggers propagate to the ipsdk root by default +Child loggers returned by `get_logger(name)` SHALL have `propagate=True` (stdlib default) so that level changes on the `ipsdk` root logger apply automatically. + +#### Scenario: Level inheritance via propagation +- **WHEN** `set_level(DEBUG)` is called on the module +- **AND** `get_logger("mylib")` is called after +- **THEN** the child logger propagates records up to the `ipsdk` root handler diff --git a/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/tasks.md b/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/tasks.md new file mode 100644 index 0000000..17762e0 --- /dev/null +++ b/openspec/changes/archive/2026-03-19-logging-named-loggers-and-reset/tasks.md @@ -0,0 +1,37 @@ +## 1. Registry Infrastructure + +- [x] 1.1 Add `_extra_logger_prefixes: set[str]` module-level set and `_registry_lock = threading.Lock()` to `logging.py` +- [x] 1.2 Implement `register_logger_prefix(prefix: str) -> None` with lock-protected write and idempotent set insertion +- [x] 1.3 Update `_get_loggers()` to merge `{metadata.name, "httpx"}` with `_extra_logger_prefixes` when discovering loggers + +## 2. Named Loggers + +- [x] 2.1 Update `get_logger(name: str | None = None)` signature and add `ValueError` guard when `name` starts with `metadata.name + "."` +- [x] 2.2 Return `logging.getLogger(f"{metadata.name}.{name}")` for non-None names; preserve existing root-logger path for `None` + +## 3. Dependency Logger Reset + +- [x] 3.1 Implement `reset_logger(name: str) -> bool` — capture pre-reset state (handlers + level), call `handler.close()` on each, remove handlers, set level to `NOTSET`, set `propagate=True`, return bool +- [x] 3.2 Export `reset_logger` in module public surface (add to module-level docstring listing) + +## 4. One-shot loggers Parameter + +- [x] 4.1 Add `loggers: list[str] | None = None` keyword-only parameter to `set_level()`; when provided, set level on each named logger in addition to the managed set (do not persist to registry) +- [x] 4.2 Add `loggers: list[str] | None = None` keyword-only parameter to `initialize()`; when provided, apply the same handler-clear + stderr-handler + NONE-level treatment to each named logger (do not persist to registry) + +## 5. Tests + +- [x] 5.1 Add tests for `get_logger(None)` and `get_logger()` return the `ipsdk` root logger (regression) +- [x] 5.2 Add tests for `get_logger("mylib")` returns logger named `"ipsdk.mylib"` and same instance on second call +- [x] 5.3 Add test for `get_logger("ipsdk.mylib")` raises `ValueError` +- [x] 5.4 Add tests for `reset_logger` on a logger with handlers: handlers removed, closed, level reset, propagate True, returns True +- [x] 5.5 Add test for `reset_logger` on a logger with no handlers and NOTSET level returns False +- [x] 5.6 Add tests for `register_logger_prefix` — idempotent, appears in `_extra_logger_prefixes`, discovered by `_get_loggers()` +- [x] 5.7 Add tests for `set_level(lvl, loggers=["somelib"])` sets level on the named logger without persisting to registry +- [x] 5.8 Add tests for `initialize(loggers=["somelib"])` clears and reinitializes the named logger without persisting to registry +- [x] 5.9 Verify 100% coverage (`make coverage`) passes with no new uncovered lines + +## 6. Docs & Cleanup + +- [x] 6.1 Update module docstring in `logging.py` to document new public functions (`get_logger` signature, `reset_logger`, `register_logger_prefix`) +- [x] 6.2 Run `make ci` and confirm all checks pass diff --git a/openspec/specs/dependency-logger-reset/spec.md b/openspec/specs/dependency-logger-reset/spec.md new file mode 100644 index 0000000..9609e34 --- /dev/null +++ b/openspec/specs/dependency-logger-reset/spec.md @@ -0,0 +1,36 @@ +## ADDED Requirements + +### Requirement: reset_logger clears handlers and restores propagation on any named logger +`ipsdk.logging.reset_logger(name)` SHALL remove all handlers from the named stdlib logger, reset its level to `NOTSET`, and set `propagate=True`, regardless of whether the logger is in the ipsdk namespace. + +#### Scenario: Reset a third-party logger +- **WHEN** `reset_logger("httpcore")` is called +- **THEN** `logging.getLogger("httpcore")` has no handlers +- **AND** its level is `logging.NOTSET` +- **AND** its `propagate` attribute is `True` + +#### Scenario: Reset an ipsdk child logger +- **WHEN** a child logger `"ipsdk.mylib"` has been configured with handlers and a level +- **AND** `reset_logger("ipsdk.mylib")` is called +- **THEN** `logging.getLogger("ipsdk.mylib")` has no handlers and level `NOTSET` + +### Requirement: reset_logger returns True if the logger had non-default state +`reset_logger` SHALL return `True` if the logger had at least one handler OR a non-NOTSET level before the reset, and `False` otherwise. + +#### Scenario: Logger had handlers +- **WHEN** `logging.getLogger("httpcore")` has one or more handlers attached +- **AND** `reset_logger("httpcore")` is called +- **THEN** the return value is `True` + +#### Scenario: Logger had no handlers or level +- **WHEN** `logging.getLogger("unknown.lib")` has no handlers and level `NOTSET` +- **AND** `reset_logger("unknown.lib")` is called +- **THEN** the return value is `False` + +### Requirement: reset_logger closes handlers before removing them +`reset_logger` SHALL call `handler.close()` on each handler before removing it, consistent with how `initialize()` manages handlers. + +#### Scenario: Handler is closed +- **WHEN** a logger has a `StreamHandler` attached +- **AND** `reset_logger` is called +- **THEN** the handler's `close()` method is called exactly once before it is removed diff --git a/openspec/specs/managed-logger-registry/spec.md b/openspec/specs/managed-logger-registry/spec.md new file mode 100644 index 0000000..8873a3c --- /dev/null +++ b/openspec/specs/managed-logger-registry/spec.md @@ -0,0 +1,50 @@ +## ADDED Requirements + +### Requirement: register_logger_prefix adds a prefix to the managed logger registry +`ipsdk.logging.register_logger_prefix(prefix)` SHALL add the given string to the module-level `_extra_logger_prefixes` set so that subsequent calls to `_get_loggers()`, `set_level()`, and `initialize()` include loggers whose names start with that prefix. + +#### Scenario: Registered prefix is included in logger discovery +- **WHEN** `register_logger_prefix("httpcore")` is called +- **AND** `_get_loggers()` is called (with cache cleared) +- **THEN** any existing logger named `"httpcore"` or `"httpcore.*"` is included in the returned set + +#### Scenario: Duplicate registration is idempotent +- **WHEN** `register_logger_prefix("httpcore")` is called twice +- **THEN** `_extra_logger_prefixes` contains `"httpcore"` exactly once + +### Requirement: _get_loggers includes extra prefixes from the registry +`_get_loggers()` SHALL discover loggers matching `metadata.name`, `"httpx"`, AND every prefix in `_extra_logger_prefixes`. + +#### Scenario: Default discovery without extra prefixes +- **WHEN** `_extra_logger_prefixes` is empty +- **THEN** `_get_loggers()` returns only loggers whose names start with `"ipsdk"` or `"httpx"` + +#### Scenario: Discovery with extra prefix registered +- **WHEN** `register_logger_prefix("mylib")` has been called +- **AND** `logging.getLogger("mylib.core")` exists in the logging manager +- **THEN** `_get_loggers()` includes the `"mylib.core"` logger + +### Requirement: set_level accepts an optional loggers parameter for one-shot management +`set_level(lvl, *, propagate=False, loggers=None)` SHALL accept an optional `loggers: list[str] | None` parameter. When provided, the named loggers SHALL have their level set to `lvl` in addition to the normal managed set. The extra names SHALL NOT be persisted to `_extra_logger_prefixes`. + +#### Scenario: One-shot logger level set +- **WHEN** `set_level(DEBUG, loggers=["boto3"])` is called +- **THEN** `logging.getLogger("boto3").level` is `DEBUG` +- **AND** `"boto3"` is NOT in `_extra_logger_prefixes` after the call + +### Requirement: initialize accepts an optional loggers parameter for one-shot initialization +`initialize(loggers=None)` SHALL accept an optional `loggers: list[str] | None` parameter. When provided, the named loggers SHALL be reset (handlers cleared, level set to NONE) in addition to the normally managed set. The extra names SHALL NOT be persisted to `_extra_logger_prefixes`. + +#### Scenario: One-shot logger initialization +- **WHEN** `initialize(loggers=["urllib3"])` is called +- **THEN** `logging.getLogger("urllib3")` has a single `StreamHandler` pointing to `stderr` +- **AND** its level is `NONE` +- **AND** `"urllib3"` is NOT in `_extra_logger_prefixes` after the call + +### Requirement: registry writes are thread-safe +`register_logger_prefix` SHALL use the existing `_logger_cache_lock` (or an equivalent lock) to protect writes to `_extra_logger_prefixes`. + +#### Scenario: Concurrent registration +- **WHEN** multiple threads call `register_logger_prefix` concurrently with different prefixes +- **THEN** all prefixes are present in `_extra_logger_prefixes` after all threads complete +- **AND** no `RuntimeError` or data corruption occurs diff --git a/openspec/specs/named-loggers/spec.md b/openspec/specs/named-loggers/spec.md new file mode 100644 index 0000000..7d0d9e0 --- /dev/null +++ b/openspec/specs/named-loggers/spec.md @@ -0,0 +1,38 @@ +## ADDED Requirements + +### Requirement: get_logger returns root logger when name is None +`ipsdk.logging.get_logger()` and `ipsdk.logging.get_logger(None)` SHALL both return the `logging.Logger` instance registered under the `ipsdk` root name, preserving existing behaviour. + +#### Scenario: Call with no argument +- **WHEN** `get_logger()` is called with no arguments +- **THEN** the returned logger's name is `"ipsdk"` + +#### Scenario: Call with None +- **WHEN** `get_logger(None)` is called +- **THEN** the returned logger's name is `"ipsdk"` + +### Requirement: get_logger returns named child logger under ipsdk namespace +When a non-None `name` is passed, `get_logger(name)` SHALL return a `logging.Logger` whose full name is `"ipsdk."`. + +#### Scenario: Named child logger +- **WHEN** `get_logger("mylib")` is called +- **THEN** the returned logger's name is `"ipsdk.mylib"` + +#### Scenario: Same instance on repeated calls +- **WHEN** `get_logger("mylib")` is called twice +- **THEN** both calls return the identical `Logger` object (stdlib behaviour via `logging.getLogger`) + +### Requirement: get_logger rejects names that already include the ipsdk prefix +If `name` starts with `"ipsdk."`, `get_logger` SHALL raise `ValueError` to prevent double-prefixing (e.g., `"ipsdk.ipsdk.mylib"`). + +#### Scenario: Prefix already present +- **WHEN** `get_logger("ipsdk.mylib")` is called +- **THEN** `ValueError` is raised with a message indicating the prefix must not be included + +### Requirement: Named child loggers propagate to the ipsdk root by default +Child loggers returned by `get_logger(name)` SHALL have `propagate=True` (stdlib default) so that level changes on the `ipsdk` root logger apply automatically. + +#### Scenario: Level inheritance via propagation +- **WHEN** `set_level(DEBUG)` is called on the module +- **AND** `get_logger("mylib")` is called after +- **THEN** the child logger propagates records up to the `ipsdk` root handler diff --git a/src/ipsdk/logging.py b/src/ipsdk/logging.py index d071af5..a501856 100644 --- a/src/ipsdk/logging.py +++ b/src/ipsdk/logging.py @@ -20,7 +20,9 @@ - Configuration functions: - set_level() - Set logging level with optional httpx/httpcore control - initialize() - Reset and initialize logging handlers - - get_logger() - Get the main application logger + - get_logger() - Get the root ipsdk logger or a named child logger + - reset_logger() - Reset any named logger to a clean default state + - register_logger_prefix() - Add a prefix to the managed-logger registry - Sensitive data filtering: - enable_sensitive_data_filtering() - Enable PII/credential redaction - disable_sensitive_data_filtering() - Disable filtering @@ -89,6 +91,23 @@ def process_data(data): logging.info("User credentials: api_key=secret123456789012345") # Output: "User credentials: [REDACTED_API_KEY]" + Named child loggers and dependency management:: + + from ipsdk import logging + + # Get a named child logger for a sub-library + lib_logger = logging.get_logger("mylib") # → "ipsdk.mylib" + + # Register a third-party prefix so set_level manages it automatically + logging.register_logger_prefix("httpcore") + logging.set_level(logging.DEBUG) # also sets httpcore to DEBUG + + # Silence a noisy dependency without the registry + logging.reset_logger("boto3") + + # One-shot level set for extra loggers without registering them + logging.set_level(logging.WARNING, loggers=["urllib3"]) + Controlling httpx/httpcore logging:: from ipsdk import logging @@ -158,6 +177,9 @@ def process_data(data): # Thread-safe logger cache access _logger_cache_lock = threading.Lock() +# Registry of extra logger prefixes managed alongside ipsdk.* and httpx +_extra_logger_prefixes: set[str] = set() + def log(lvl: int, msg: str) -> None: """Send the log message with the specified level. @@ -334,35 +356,125 @@ def _get_loggers() -> set[logging.Logger]: """ with _logger_cache_lock: loggers = set() + # Merge built-in prefixes with the configurable registry + prefixes = tuple({metadata.name, "httpx"} | _extra_logger_prefixes) # Create a copy of the logger dictionary for thread safety logger_dict_copy = logging.Logger.manager.loggerDict.copy() for name in logger_dict_copy: # Verify logger still exists and matches our namespace - if ( - name.startswith((metadata.name, "httpx")) - and name in logging.Logger.manager.loggerDict - ): + if name.startswith(prefixes) and name in logging.Logger.manager.loggerDict: loggers.add(logging.getLogger(name)) return loggers -def get_logger() -> logging.Logger: - """Get the main application logger. +def register_logger_prefix(prefix: str) -> None: + """Register an extra logger prefix to be managed by ipsdk logging. + + Adds the given prefix to the module-level registry so that loggers whose + names start with it are automatically included in `_get_loggers()` discovery + and therefore managed by `set_level()` and `initialize()`. + + Registration is idempotent — registering the same prefix more than once has + no additional effect. Registration is expected at application startup, before + any active logging occurs. + + This function is thread-safe. Args: - None + prefix (str): Logger name prefix to register (e.g. ``"httpcore"``, + ``"mylib"``). Returns: - logging.Logger: The logger instance for the ipsdk application. + None Raises: None """ + with _logger_cache_lock: + _extra_logger_prefixes.add(prefix) + _get_loggers.cache_clear() + + +def get_logger(name: str | None = None) -> logging.Logger: + """Get a logger from the ipsdk hierarchy. + + With no arguments (or ``name=None``) returns the root ``ipsdk`` logger, + preserving existing behaviour. When *name* is provided, returns a named + child logger registered as ``ipsdk.``. Child loggers propagate to + the root ``ipsdk`` logger by default, so a single ``set_level()`` call + applies to the whole hierarchy. + + Args: + name (str | None): Short name for a child logger (e.g. ``"mylib"``). + Must not include the ``ipsdk.`` prefix — pass ``"mylib"``, not + ``"ipsdk.mylib"``. Defaults to ``None`` (root logger). + + Returns: + logging.Logger: The requested logger instance. + + Raises: + ValueError: If *name* starts with ``"ipsdk."`` to prevent + double-prefixing (e.g. ``"ipsdk.ipsdk.mylib"``). + """ + if name is not None: + prefix = metadata.name + "." + if name.startswith(prefix): + msg = ( + f"Logger name must not include the '{metadata.name}.' prefix; " + f"got '{name}'. Pass the short name only, e.g. " + f"get_logger('{name[len(prefix) :]}')" + ) + raise ValueError(msg) + return logging.getLogger(f"{metadata.name}.{name}") return logging.getLogger(metadata.name) -def set_level(lvl: int | str, *, propagate: bool = False) -> None: +def reset_logger(name: str) -> bool: + """Reset an arbitrary named logger to a clean, un-configured state. + + Removes all handlers (closing each one), resets the log level to + ``NOTSET``, and sets ``propagate=True``. This lets callers silence + third-party library loggers (e.g. ``"httpcore"``, ``"boto3"``) or clean + up ipsdk child loggers without manually reaching into stdlib internals. + + Only the exact logger named *name* is affected — child loggers under that + name are not touched. To reset a whole sub-tree call ``reset_logger`` + for each logger name explicitly. + + This function is NOT thread-safe with respect to concurrent log emission + from the target logger. Call it at startup before active logging begins. + + Args: + name (str): Exact name of the stdlib logger to reset (e.g. + ``"httpcore"``, ``"ipsdk.mylib"``). + + Returns: + bool: ``True`` if the logger had at least one handler or a non-NOTSET + level before the reset; ``False`` if it was already in its default + state. + + Raises: + None + """ + logger = logging.getLogger(name) + had_state = bool(logger.handlers) or logger.level != logging.NOTSET + handlers = logger.handlers[:] + for handler in handlers: + logger.removeHandler(handler) + handler.close() + logger.setLevel(logging.NOTSET) + logger.propagate = True + gc.collect() + return had_state + + +def set_level( + lvl: int | str, + *, + propagate: bool = False, + loggers: list[str] | None = None, +) -> None: """Set logging level for all loggers in the current Python process. Args: @@ -371,6 +483,11 @@ def set_level(lvl: int | str, *, propagate: bool = False) -> None: to disable all logging. propagate (bool): Setting this value to True will also turn on logging for httpx and httpcore. Defaults to False. + loggers (list[str] | None): Optional list of extra logger names (e.g. + ``["boto3", "urllib3"]``) whose level will be set to *lvl* in + addition to the normally managed set. These names are NOT + persisted to the managed-logger registry — they apply only for + this call. Defaults to ``None``. Returns: None @@ -400,6 +517,10 @@ def set_level(lvl: int | str, *, propagate: bool = False) -> None: for logger in _get_loggers(): logger.setLevel(lvl) + if loggers: + for extra_name in loggers: + logging.getLogger(extra_name).setLevel(lvl) + def enable_sensitive_data_filtering() -> None: """Enable sensitive data filtering in log messages. @@ -543,7 +664,7 @@ def remove_sensitive_data_pattern(name: str) -> bool: return heuristics.get_scanner().remove_pattern(name) -def initialize() -> None: +def initialize(loggers: list[str] | None = None) -> None: """Initialize logging configuration for the application. Resets all managed loggers by removing their existing handlers and @@ -560,6 +681,14 @@ def initialize() -> None: Repeated calls may cause memory leaks if loggers are created between invocations. + Args: + loggers (list[str] | None): Optional list of extra logger names (e.g. + ``["urllib3"]``) to initialize alongside the managed set. Each + named logger will have its handlers cleared and replaced with a + stderr ``StreamHandler`` at level ``NONE``. These names are NOT + persisted to the managed-logger registry — they apply only for + this call. Defaults to ``None``. + Returns: None @@ -583,5 +712,18 @@ def initialize() -> None: logger.setLevel(NONE) logger.propagate = False + if loggers: + for extra_name in loggers: + extra_logger = logging.getLogger(extra_name) + extra_handlers = extra_logger.handlers[:] + for handler in extra_handlers: + extra_logger.removeHandler(handler) + handler.close() + stream_handler = logging.StreamHandler(sys.stderr) + stream_handler.setFormatter(logging.Formatter(logging_message_format)) + extra_logger.addHandler(stream_handler) + extra_logger.setLevel(NONE) + extra_logger.propagate = False + # Force garbage collection of closed handlers to prevent memory leaks gc.collect() diff --git a/tests/test_logging.py b/tests/test_logging.py index a5ec59f..bf5c8f8 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -746,6 +746,28 @@ def error_func(): assert "exception" in str(exit_calls[0]) assert "ms)" in str(exit_calls[0]) + def test_trace_async_exception_handling(self): + """Test trace decorator logs exception exit for async functions.""" + with patch("ipsdk.logging.log") as mock_log: + + @ipsdk_logging.trace + async def async_error_func(): + msg = "async error" + raise ValueError(msg) + + with contextlib.suppress(ValueError): + asyncio.run(async_error_func()) + + assert mock_log.call_count == 2 + calls = mock_log.call_args_list + assert any( + "→" in str(call) and "async_error_func" in str(call) for call in calls + ) + exit_calls = [call for call in calls if "←" in str(call)] + assert len(exit_calls) == 1 + assert "exception" in str(exit_calls[0]) + assert "ms)" in str(exit_calls[0]) + class TestFormatString: """Test the logging message format string.""" @@ -758,3 +780,186 @@ def test_logging_message_format_exists(self): assert "%(name)s" in ipsdk_logging.logging_message_format assert "%(levelname)s" in ipsdk_logging.logging_message_format assert "%(message)s" in ipsdk_logging.logging_message_format + + +class TestGetLoggerNamed: + """Test named-logger behaviour of get_logger.""" + + def test_get_logger_no_args_returns_root(self): + """get_logger() returns the ipsdk root logger.""" + logger = ipsdk_logging.get_logger() + assert isinstance(logger, logging.Logger) + assert logger.name == metadata.name + + def test_get_logger_none_returns_root(self): + """get_logger(None) returns the ipsdk root logger.""" + logger = ipsdk_logging.get_logger(None) + assert isinstance(logger, logging.Logger) + assert logger.name == metadata.name + + def test_get_logger_name_returns_child(self): + """get_logger('mylib') returns logger named 'ipsdk.mylib'.""" + logger = ipsdk_logging.get_logger("mylib") + assert isinstance(logger, logging.Logger) + assert logger.name == f"{metadata.name}.mylib" + + def test_get_logger_name_same_instance(self): + """Calling get_logger with the same name twice returns the same object.""" + l1 = ipsdk_logging.get_logger("samelib") + l2 = ipsdk_logging.get_logger("samelib") + assert l1 is l2 + + def test_get_logger_name_with_prefix_raises(self): + """get_logger raises ValueError if name starts with 'ipsdk.'.""" + with pytest.raises(ValueError, match=r"must not include"): + ipsdk_logging.get_logger(f"{metadata.name}.something") + + def test_get_logger_child_propagates_to_root(self): + """Child logger propagate flag is True so level flows from ipsdk root.""" + child = ipsdk_logging.get_logger("proptest") + assert child.propagate is True + + +class TestResetLogger: + """Test reset_logger behaviour.""" + + def test_reset_logger_removes_handlers_and_returns_true(self): + """reset_logger removes all handlers, closes them, returns True.""" + target = logging.getLogger("ipsdk_test_reset_with_handlers") + mock_handler = Mock(spec=logging.StreamHandler) + # handlers list must be mutable so simulate properly + target.handlers = [mock_handler] + target.setLevel(logging.DEBUG) + + result = ipsdk_logging.reset_logger("ipsdk_test_reset_with_handlers") + + assert result is True + assert target.handlers == [] + assert target.level == logging.NOTSET + assert target.propagate is True + mock_handler.close.assert_called_once() + + def test_reset_logger_no_state_returns_false(self): + """reset_logger returns False when logger had no handlers and NOTSET level.""" + name = "ipsdk_test_reset_clean_logger_xyz" + target = logging.getLogger(name) + # Ensure clean state + target.handlers = [] + target.setLevel(logging.NOTSET) + target.propagate = True + + result = ipsdk_logging.reset_logger(name) + + assert result is False + + def test_reset_logger_nondefault_level_returns_true(self): + """reset_logger returns True when only the level was non-default.""" + name = "ipsdk_test_reset_level_only" + target = logging.getLogger(name) + target.handlers = [] + target.setLevel(logging.WARNING) + + result = ipsdk_logging.reset_logger(name) + + assert result is True + assert target.level == logging.NOTSET + + def test_reset_logger_sets_propagate_true(self): + """reset_logger always sets propagate=True.""" + name = "ipsdk_test_reset_propagate" + target = logging.getLogger(name) + target.propagate = False + target.setLevel(logging.ERROR) + + ipsdk_logging.reset_logger(name) + + assert target.propagate is True + + +class TestManagedLoggerRegistry: + """Test register_logger_prefix and its effect on _get_loggers.""" + + def setup_method(self): + """Clear the registry before each test to avoid cross-test pollution.""" + ipsdk_logging._extra_logger_prefixes.clear() + ipsdk_logging._get_loggers.cache_clear() + + def teardown_method(self): + """Restore clean registry state after each test.""" + ipsdk_logging._extra_logger_prefixes.clear() + ipsdk_logging._get_loggers.cache_clear() + + def test_register_prefix_adds_to_set(self): + """register_logger_prefix adds the prefix to _extra_logger_prefixes.""" + ipsdk_logging.register_logger_prefix("myprefix") + assert "myprefix" in ipsdk_logging._extra_logger_prefixes + + def test_register_prefix_idempotent(self): + """Registering the same prefix twice keeps it once.""" + ipsdk_logging.register_logger_prefix("myprefix") + ipsdk_logging.register_logger_prefix("myprefix") + occurrences = sum( + 1 for p in ipsdk_logging._extra_logger_prefixes if p == "myprefix" + ) + assert occurrences == 1 + + def test_registered_prefix_discovered_by_get_loggers(self): + """Loggers matching a registered prefix appear in _get_loggers().""" + # Create a logger under the new prefix + logging.getLogger("registrytest.core") + ipsdk_logging.register_logger_prefix("registrytest") + ipsdk_logging._get_loggers.cache_clear() + + names = {lg.name for lg in ipsdk_logging._get_loggers()} + assert "registrytest.core" in names + + def test_unregistered_prefix_not_in_get_loggers(self): + """Loggers not matching any prefix are excluded from _get_loggers().""" + logging.getLogger("unregisteredlib.sub") + ipsdk_logging._get_loggers.cache_clear() + + names = {lg.name for lg in ipsdk_logging._get_loggers()} + assert "unregisteredlib.sub" not in names + + def test_set_level_loggers_param_sets_level(self): + """set_level with loggers= sets level on named loggers.""" + with patch("ipsdk.logging.get_logger") as mock_get_logger: + mock_root = Mock() + mock_get_logger.return_value = mock_root + + target = logging.getLogger("oneshot_set_level_lib") + target.setLevel(logging.NOTSET) + + ipsdk_logging.set_level(logging.DEBUG, loggers=["oneshot_set_level_lib"]) + + assert target.level == logging.DEBUG + + def test_set_level_loggers_param_not_persisted(self): + """set_level with loggers= does not persist names to _extra_logger_prefixes.""" + with patch("ipsdk.logging.get_logger") as mock_get_logger: + mock_root = Mock() + mock_get_logger.return_value = mock_root + + ipsdk_logging.set_level(logging.DEBUG, loggers=["oneshot_persist_check"]) + + assert "oneshot_persist_check" not in ipsdk_logging._extra_logger_prefixes + + def test_initialize_loggers_param_reinitializes_logger(self): + """initialize with loggers= clears and sets up the named logger.""" + target = logging.getLogger("oneshot_init_lib") + target.setLevel(logging.DEBUG) + # Add a dummy handler so we can confirm it's replaced + dummy = logging.StreamHandler(sys.stderr) + target.addHandler(dummy) + + ipsdk_logging.initialize(loggers=["oneshot_init_lib"]) + + assert len(target.handlers) == 1 + assert isinstance(target.handlers[0], logging.StreamHandler) + assert target.level == ipsdk_logging.NONE + assert target.propagate is False + + def test_initialize_loggers_param_not_persisted(self): + """initialize with loggers= does not persist names to _extra_logger_prefixes.""" + ipsdk_logging.initialize(loggers=["oneshot_init_persist_check"]) + assert "oneshot_init_persist_check" not in ipsdk_logging._extra_logger_prefixes