diff --git a/CHANGELOG.md b/CHANGELOG.md index a8a51db..91a38b2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,34 @@ All notable changes to this project are documented in this file. ## Unreleased +- Phase 7, advanced context & stdlib bridge, complete: + - `bind_context(**values)` — a `contextvars`-based context manager that + merges `values` into every `Logger` call underneath it, through any + method and any number of function calls deep, without threading them + through each signature by hand. Isolated per thread/asyncio task; + nested blocks merge, with the innermost value winning on key collision + (an explicit call-site `meta` value still wins over anything bound this + way). `current_context()` reads the merged dict directly. + - `exc_info=` on every `Logger` method (`logger.error("failed", + exc_info=e)`) — accepts the same shapes stdlib `logging` does (an + exception instance, `True` for the exception currently being handled, + or an explicit `(type, value, traceback)` tuple), formats a traceback + into `meta["stack"]`, and is never kept in `meta` as the raw exception + object, since that isn't serializable. `format_exc_info()` is exported + directly for anything that wants the same formatting standalone. + - `LogQuillHandler` — a `logging.Handler` subclass that bridges stdlib + `logging` calls (including from third-party libraries) into a LogQuill + `Logger`, so they flow through the same transports and plugin pipeline + as a native `.info()`/`.error()`/... call. `extra=` fields land in + `meta`; an attached `exc_info` is formatted into `meta["stack"]` the + same way the `Logger`'s own `exc_info=` kwarg is. Level filtering still + applies on top of whatever the stdlib logger/handler's own level is set to. + - `RateLimitPlugin(max_records, per_seconds)` — drops records once a key + (by default `(logger, level)`, or a custom `key_func`) exceeds + `max_records` within a rolling per-key window, to cap a noisy loop + without silencing the logger's other messages. Bounded by `max_keys` + distinct keys tracked at once, evicting the least-recently-seen key's + window to make room for a new one. - Phase 6, async worker, shutdown & serverless safety, complete: - `AsyncWorker` — a bounded, in-memory queue backed by a single daemon thread, with a configurable `backpressure` policy for what happens once diff --git a/README.md b/README.md index 72d0fc1..9bf3575 100644 --- a/README.md +++ b/README.md @@ -30,7 +30,7 @@ for what's landed so far. - **Non-blocking async dispatch** — `Logger(async_dispatch=True)` moves transport writes onto a background thread with a bounded queue and a configurable backpressure policy (`drop_oldest`/`drop_newest`/`block`); `flush()`/`flush_async()` and a `with_lambda`/`with_cloud_function`/`with_azure_function` decorator make serverless shutdown safe — see [Async dispatch & serverless safety](#async-dispatch--serverless-safety) - **Zero required runtime dependencies** — stdlib only; `aiohttp` is opt-in, for async HTTP - **Typed throughout** — `mypy --strict` clean on the public API -- *(planned)* `contextvars`-based context propagation — see `CHANGELOG.md` +- **Context propagation, exception capture & the stdlib bridge** — `bind_context()` (`contextvars`-based, no manual passing), `exc_info=` on any `Logger` method (formatted traceback into `meta["stack"]`), `LogQuillHandler` (bridges stdlib `logging` into a `Logger`), and `RateLimitPlugin` — see [Context propagation, exception capture & the stdlib bridge](#context-propagation-exception-capture--the-stdlib-bridge) ## Install @@ -780,6 +780,80 @@ the same decorator under a name that reads naturally at each platform's own handler definition — the flush-before-return behavior is identical across all three. +## Context propagation, exception capture & the stdlib bridge + +`bind_context()` binds request-scoped values for a `with` block — every +`Logger` call underneath it, through any method and any number of function +calls deep, picks them up in `meta` automatically, without threading them +through every function signature by hand: + +```python +from logquill import Logger, bind_context + +logger = Logger("app") + +def process(): + return logger.info("processing") # no request_id passed in — picked up from context + +with bind_context(request_id="req-42"): + record = process() + +assert record["meta"] == {"request_id": "req-42"} +``` + +It's backed by a `contextvars.ContextVar`, so concurrent asyncio tasks and +threads each see their own bound context; nested `bind_context` blocks +merge, and an explicit call-site value still wins over anything bound this +way — the same override rule `ContextPlugin` uses. + +Pass `exc_info=` (an exception instance, `True` for the exception currently +being handled, or an explicit `(type, value, traceback)` tuple — the same +shapes stdlib `logging` accepts) to any `Logger` method to capture a +formatted traceback into `meta["stack"]`: + +```python +from logquill import Logger + +logger = Logger("app") + +try: + 1 / 0 +except ZeroDivisionError as exc: + record = logger.error("payment failed", exc_info=exc, order_id=42) + +assert record["meta"]["order_id"] == 42 +assert "ZeroDivisionError" in record["meta"]["stack"] +``` + +`LogQuillHandler` bridges stdlib `logging` calls — including from +third-party libraries you don't control — into a `Logger`, so they flow +through the same transports and plugins instead of needing every call site +rewritten: + +```python +import logging +from logquill import Logger, LogQuillHandler + +logger = Logger("app") +logging.getLogger().addHandler(LogQuillHandler(logger)) + +logging.getLogger("some.library").warning("retrying", extra={"attempt": 2}) +# -> flows through `logger`'s transports as a WARN record with meta: {'attempt': 2} +``` + +`RateLimitPlugin` caps how many records with the same `(logger, level)` (or +a custom `key_func`) pass through per rolling window — for a noisy retry +loop that would otherwise flood a transport: + +```python +from logquill import Logger, RateLimitPlugin + +logger = Logger("app", plugins=[RateLimitPlugin(max_records=5, per_seconds=60)]) + +for _ in range(100): + logger.error("connection refused") # only the first 5 per minute ship +``` + ## Development ```bash diff --git a/logquill/__init__.py b/logquill/__init__.py index c2744a2..0bf8104 100644 --- a/logquill/__init__.py +++ b/logquill/__init__.py @@ -1,6 +1,9 @@ from logquill.adapters.base import LogQuillAdapter from logquill.config import load_config, logger_from_env, logger_from_file +from logquill.context import bind_context, current_context +from logquill.exceptions import format_exc_info from logquill.formatter import Formatter, JSONFormatter +from logquill.handler import LogQuillHandler from logquill.levels import Level, parse_level from logquill.logger import Logger from logquill.plugins.alerting_plugin import AlertingPlugin @@ -9,6 +12,7 @@ from logquill.plugins.pagerduty_alert_plugin import PagerDutyAlertPlugin from logquill.plugins.pii_redact_plugin import PIIRedactPlugin from logquill.plugins.plugin import FunctionPlugin, Plugin +from logquill.plugins.rate_limit_plugin import RateLimitPlugin from logquill.plugins.redact_plugin import RedactPlugin from logquill.plugins.run_plugin import RunPlugin from logquill.plugins.sampling_plugin import SamplingPlugin @@ -69,6 +73,7 @@ "KafkaTransport", "Level", "LogQuillAdapter", + "LogQuillHandler", "LogRecord", "Logger", "MongoDBTransport", @@ -80,6 +85,7 @@ "PostgresTransport", "PubSubTransport", "RabbitMQTransport", + "RateLimitPlugin", "RedactPlugin", "RedisTransport", "RunPlugin", @@ -92,6 +98,9 @@ "TamperEvidentPlugin", "TraceContextPlugin", "Transport", + "bind_context", + "current_context", + "format_exc_info", "load_config", "logger_from_env", "logger_from_file", diff --git a/logquill/context.py b/logquill/context.py new file mode 100644 index 0000000..bd2f28c --- /dev/null +++ b/logquill/context.py @@ -0,0 +1,40 @@ +from __future__ import annotations + +import contextlib +from contextvars import ContextVar +from typing import Any, Iterator + +_current_context: ContextVar[dict[str, Any] | None] = ContextVar("logquill_context", default=None) + + +def current_context() -> dict[str, Any]: + """The merged key/value pairs bound by every `bind_context()` block + currently active in this execution context (thread or asyncio task). + """ + return _current_context.get() or {} + + +@contextlib.contextmanager +def bind_context(**values: Any) -> Iterator[None]: + """Merge `values` into the request-scoped context for the duration of + this `with` block — every `Logger` call underneath it, through any + method and any number of function calls deep, picks them up in `meta` + automatically, without threading them through every signature by hand: + + with bind_context(request_id="abc123"): + handle_request() # any logging in here, or in what it calls, + # gets meta["request_id"] = "abc123" for free + + Backed by a `contextvars.ContextVar`, so concurrent asyncio tasks and + threads each see their own bound context — binding in one never leaks + into another. Blocks nest by merging (an inner `bind_context` value + wins over an outer one on key collision, the same way an explicit + call-site `meta` value wins over anything bound here); exiting restores + exactly the context that was active before the block started. + """ + parent = current_context() + token = _current_context.set({**parent, **values}) + try: + yield + finally: + _current_context.reset(token) diff --git a/logquill/exceptions.py b/logquill/exceptions.py new file mode 100644 index 0000000..29d7c5e --- /dev/null +++ b/logquill/exceptions.py @@ -0,0 +1,47 @@ +from __future__ import annotations + +import sys +import traceback +from types import TracebackType +from typing import Literal, Union + +# `Literal[True]` rather than `bool`: `False` behaves identically to `None` +# (both mean "nothing to format", handled by the `not exc_info` check below), +# so it isn't a distinct case worth widening the type for — and keeping it +# out lets the branches below narrow cleanly under `mypy --strict`. +ExcInfoArg = Union[ + Literal[True], + BaseException, + "tuple[type[BaseException], BaseException, TracebackType | None]", + None, +] + + +def format_exc_info(exc_info: ExcInfoArg) -> str | None: + """Render `exc_info` as a formatted traceback string, or `None` if + there's nothing to format. Accepts the same shapes stdlib `logging` + does, so `logger.error("failed", exc_info=e)` reads exactly like the + `logging` module's own `exc_info=` kwarg: + + - `True` — format the exception currently being handled (`sys.exc_info()`) + - an exception instance — format it and its own traceback + - an explicit `(type, value, traceback)` tuple + - falsy (`False`/`None`, the default) — nothing to format + """ + if not exc_info: + return None + + exc_type: type[BaseException] | None + exc_value: BaseException | None + exc_tb: TracebackType | None + + if exc_info is True: + exc_type, exc_value, exc_tb = sys.exc_info() + if exc_type is None: + return None + elif isinstance(exc_info, BaseException): + exc_type, exc_value, exc_tb = type(exc_info), exc_info, exc_info.__traceback__ + else: + exc_type, exc_value, exc_tb = exc_info + + return "".join(traceback.format_exception(exc_type, exc_value, exc_tb)) diff --git a/logquill/handler.py b/logquill/handler.py new file mode 100644 index 0000000..a5115d7 --- /dev/null +++ b/logquill/handler.py @@ -0,0 +1,99 @@ +from __future__ import annotations + +import logging +from typing import TYPE_CHECKING, Any + +from logquill.levels import Level + +if TYPE_CHECKING: + from logquill.logger import Logger + +# Attributes every stdlib `logging.LogRecord` carries for its own bookkeeping +# (formatting, source location, timing) — excluded from the `meta` a bridged +# record produces so `meta` only ever holds what a caller passed as `extra=`, +# the same shape a native LogQuill call would produce. +_STDLIB_RECORD_ATTRS = frozenset( + { + "name", + "msg", + "args", + "levelname", + "levelno", + "pathname", + "filename", + "module", + "exc_info", + "exc_text", + "stack_info", + "lineno", + "funcName", + "created", + "msecs", + "relativeCreated", + "thread", + "threadName", + "processName", + "process", + "taskName", + } +) + + +def _map_level(levelno: int) -> Level: + """Stdlib `logging` levels map onto LogQuill's directly except `WARNING` + (30 in both, but named `WARN` here) and `CRITICAL` (50, named `FATAL` + here) — see the cross-language level contract in CLAUDE.md. Anything + that doesn't land exactly on a defined level (a custom intermediate + level, or `NOTSET`) rounds down to the nearest one, the same way stdlib + `logging` itself treats level thresholds as "at least this severe." + """ + if levelno >= logging.CRITICAL: + return Level.FATAL + if levelno >= logging.ERROR: + return Level.ERROR + if levelno >= logging.WARNING: + return Level.WARN + if levelno >= logging.INFO: + return Level.INFO + if levelno >= logging.DEBUG: + return Level.DEBUG + return Level.TRACE + + +class LogQuillHandler(logging.Handler): + """Bridges stdlib `logging` calls into a LogQuill `Logger`, so output + from third-party libraries (or code not yet migrated off `logging`) + flows through the same transports and plugin pipeline as LogQuill's own + `.info()`/`.error()`/... calls, instead of needing every call site + rewritten: + + handler = LogQuillHandler(logger) + logging.getLogger().addHandler(handler) + + logging.getLogger("some.library").warning("retrying", extra={"attempt": 2}) + # -> logger.warn("retrying", attempt=2) via the same transports/plugins + + Any `extra=` fields passed to the stdlib call land in `meta` exactly + like keyword args to a native LogQuill call would; an attached + `exc_info` is formatted into `meta["stack"]` the same way `Logger`'s own + `exc_info=` kwarg is. Level filtering still goes through the wrapped + `Logger`'s own `set_level()` (via its ordinary `_log` path), on top of + whatever this handler's or the stdlib logger's own level is set to. + """ + + def __init__(self, logger: Logger, level: int = logging.NOTSET) -> None: + super().__init__(level) + self._logger = logger + + def emit(self, record: logging.LogRecord) -> None: + try: + meta: dict[str, Any] = { + key: value + for key, value in record.__dict__.items() + if key not in _STDLIB_RECORD_ATTRS and key != "message" + } + if record.exc_info: + meta["exc_info"] = record.exc_info + self._logger._log(_map_level(record.levelno), record.getMessage(), meta) + except Exception: + self.handleError(record) diff --git a/logquill/logger.py b/logquill/logger.py index 152e6ea..7fd7917 100644 --- a/logquill/logger.py +++ b/logquill/logger.py @@ -4,6 +4,8 @@ import logging from typing import Any +from logquill.context import current_context +from logquill.exceptions import format_exc_info from logquill.levels import Level, parse_level from logquill.plugins.context_plugin import ContextPlugin from logquill.plugins.plugin import FunctionPlugin, MiddlewareFunc, Plugin @@ -157,8 +159,18 @@ def _dispatch(self, record: LogRecord) -> None: def _log(self, level: Level, message: str, meta: dict[str, Any]) -> LogRecord | None: if level < self._level: return None + + if "exc_info" in meta: + stack = format_exc_info(meta.pop("exc_info")) + if stack is not None: + meta["stack"] = stack + record = create_record(level=level, logger=self.name, message=message, meta=meta) + bound_context = current_context() + if bound_context: + record["meta"] = {**bound_context, **record["meta"]} + parent_span_id = current_span_id() if parent_span_id is not None: record["meta"].setdefault("parent_span_id", parent_span_id) @@ -200,6 +212,12 @@ def warn(self, message: str, /, **meta: Any) -> LogRecord | None: return self._log(Level.WARN, message, meta) def error(self, message: str, /, **meta: Any) -> LogRecord | None: + """`exc_info=` (an exception instance, `True` for the exception + currently being handled, or an explicit `(type, value, traceback)` + tuple — the same shapes stdlib `logging` accepts) formats a + traceback into `meta["stack"]` and is otherwise not kept in `meta` + as-is, since a raw exception object isn't serializable. Every + `Logger` method accepts it, not just this one.""" return self._log(Level.ERROR, message, meta) def fatal(self, message: str, /, **meta: Any) -> LogRecord | None: diff --git a/logquill/plugins/rate_limit_plugin.py b/logquill/plugins/rate_limit_plugin.py new file mode 100644 index 0000000..53eef02 --- /dev/null +++ b/logquill/plugins/rate_limit_plugin.py @@ -0,0 +1,76 @@ +from __future__ import annotations + +import time +from collections import OrderedDict +from typing import Callable, Hashable + +from logquill.plugins.plugin import Plugin +from logquill.records import LogRecord + +RateLimitKeyFunc = Callable[[LogRecord], Hashable] + + +def _default_key(record: LogRecord) -> Hashable: + return (record["logger"], record["level"]) + + +class RateLimitPlugin(Plugin): + """Drops records once a key — by default `(logger, level)` — exceeds + `max_records` within a rolling `per_seconds` window, to cap a noisy loop + (a retry that logs the same error every iteration, a hot path that logs + once per request) without silencing the logger's other messages. + + Each key gets its own fixed window: the count for a key resets + `per_seconds` after that *key's own* first record in the current window, + not on a shared global clock, so unrelated keys never reset in lockstep. + + Pass `key_func` to rate-limit on something other than `(logger, level)` + — e.g. per error message, or per a `meta` field identifying the caller. + + Bounded by `max_keys` distinct keys tracked at once; past that, the + least-recently-seen key's window is evicted to make room for a new one + — the same bounded-memory trade-off `SamplingPlugin` makes for trace + buffering, since an unbounded key space (e.g. rate-limiting per user id) + would otherwise grow memory without limit. + """ + + def __init__( + self, + max_records: int, + per_seconds: float, + *, + key_func: RateLimitKeyFunc = _default_key, + max_keys: int = 1000, + clock: Callable[[], float] = time.monotonic, + ) -> None: + if max_records < 1: + raise ValueError(f"max_records must be at least 1, got {max_records!r}") + if per_seconds <= 0: + raise ValueError(f"per_seconds must be positive, got {per_seconds!r}") + self.max_records = max_records + self.per_seconds = per_seconds + self.key_func = key_func + self.max_keys = max_keys + self._clock = clock + # value: (window_start, count_in_window) + self._windows: OrderedDict[Hashable, tuple[float, int]] = OrderedDict() + + def before_log(self, record: LogRecord) -> LogRecord | None: + key = self.key_func(record) + now = self._clock() + window = self._windows.get(key) + + if window is None or now - window[0] >= self.per_seconds: + self._windows[key] = (now, 1) + self._windows.move_to_end(key) + while len(self._windows) > self.max_keys: + self._windows.popitem(last=False) + return record + + window_start, count = window + self._windows.move_to_end(key) + if count >= self.max_records: + return None + + self._windows[key] = (window_start, count + 1) + return record diff --git a/tests/test_context.py b/tests/test_context.py new file mode 100644 index 0000000..be51211 --- /dev/null +++ b/tests/test_context.py @@ -0,0 +1,90 @@ +from __future__ import annotations + +import asyncio +import concurrent.futures + +from logquill.context import bind_context, current_context +from logquill.logger import Logger + + +def test_bound_context_appears_in_meta_without_manual_passing() -> None: + logger = Logger("app.test") + + def nested_call() -> object: + return logger.info("handled") + + with bind_context(request_id="abc123"): + record = nested_call() + + assert record is not None + assert record["meta"]["request_id"] == "abc123" + + +def test_context_not_visible_outside_the_block() -> None: + logger = Logger("app.test") + + record = logger.info("before") + assert record is not None + assert "request_id" not in record["meta"] + + with bind_context(request_id="abc123"): + pass + + record = logger.info("after") + assert record is not None + assert "request_id" not in record["meta"] + + +def test_call_site_meta_overrides_bound_context() -> None: + logger = Logger("app.test") + + with bind_context(env="prod"): + record = logger.info("hello", env="staging") + + assert record is not None + assert record["meta"]["env"] == "staging" + + +def test_nested_bind_context_merges_with_inner_winning() -> None: + logger = Logger("app.test") + + with bind_context(a=1, b=1): + with bind_context(b=2, c=2): + record = logger.info("hello") + after_inner = current_context() + + assert record is not None + assert record["meta"] == {"a": 1, "b": 2, "c": 2} + assert after_inner == {"a": 1, "b": 1} + + +def test_context_is_isolated_per_thread() -> None: + logger = Logger("app.test") + results: dict[str, object] = {} + + def worker(name: str) -> None: + with bind_context(worker=name): + results[name] = logger.info("hello") + + with concurrent.futures.ThreadPoolExecutor() as pool: + list(pool.map(worker, ["t1", "t2", "t3"])) + + for name in ["t1", "t2", "t3"]: + record = results[name] + assert record is not None + assert record["meta"]["worker"] == name + + +def test_context_is_isolated_per_asyncio_task() -> None: + logger = Logger("app.test") + + async def worker(name: str) -> object: + with bind_context(task=name): + await asyncio.sleep(0) + return logger.info("hello") + + async def run() -> list[object]: + return await asyncio.gather(worker("a"), worker("b")) + + results = asyncio.run(run()) + assert [r["meta"]["task"] for r in results] == ["a", "b"] diff --git a/tests/test_exceptions.py b/tests/test_exceptions.py new file mode 100644 index 0000000..1317f87 --- /dev/null +++ b/tests/test_exceptions.py @@ -0,0 +1,78 @@ +from __future__ import annotations + +import pytest + +from logquill.exceptions import format_exc_info +from logquill.logger import Logger + + +def test_format_exc_info_from_exception_instance() -> None: + try: + raise ValueError("boom") + except ValueError as exc: + formatted = format_exc_info(exc) + + assert formatted is not None + assert "ValueError: boom" in formatted + assert "Traceback" in formatted + + +def test_format_exc_info_true_uses_active_exception() -> None: + try: + raise RuntimeError("active") + except RuntimeError: + formatted = format_exc_info(True) + + assert formatted is not None + assert "RuntimeError: active" in formatted + + +def test_format_exc_info_true_outside_except_block_returns_none() -> None: + assert format_exc_info(True) is None + + +def test_format_exc_info_falsy_returns_none() -> None: + assert format_exc_info(None) is None + assert format_exc_info(False) is None + + +def test_format_exc_info_tuple() -> None: + try: + raise KeyError("missing") + except KeyError as exc: + formatted = format_exc_info((type(exc), exc, exc.__traceback__)) + + assert formatted is not None + assert "KeyError" in formatted + + +def test_logger_error_with_exc_info_populates_stack_meta() -> None: + logger = Logger("app.test") + + try: + raise ValueError("boom") + except ValueError as exc: + record = logger.error("failed", exc_info=exc, user_id=42) + + assert record is not None + assert "exc_info" not in record["meta"] + assert record["meta"]["user_id"] == 42 + assert "ValueError: boom" in record["meta"]["stack"] + + +def test_logger_without_exc_info_has_no_stack_key() -> None: + logger = Logger("app.test") + record = logger.info("hello") + + assert record is not None + assert "stack" not in record["meta"] + + +@pytest.mark.parametrize("falsy", [None, False]) +def test_logger_falsy_exc_info_does_not_add_stack(falsy: object) -> None: + logger = Logger("app.test") + record = logger.error("failed", exc_info=falsy) + + assert record is not None + assert "stack" not in record["meta"] + assert "exc_info" not in record["meta"] diff --git a/tests/test_handler.py b/tests/test_handler.py new file mode 100644 index 0000000..326d487 --- /dev/null +++ b/tests/test_handler.py @@ -0,0 +1,82 @@ +from __future__ import annotations + +import logging + +from logquill.handler import LogQuillHandler +from logquill.logger import Logger +from logquill.transports.transport import CollectingTransport + + +def _make_stdlib_logger(handler: logging.Handler) -> logging.Logger: + stdlib_logger = logging.getLogger(f"logquill-test-{id(handler)}") + stdlib_logger.setLevel(logging.DEBUG) + stdlib_logger.propagate = False + stdlib_logger.addHandler(handler) + return stdlib_logger + + +def test_stdlib_warning_flows_through_logquill_transport() -> None: + sink = CollectingTransport() + logger = Logger("app.test", transports=[sink], level="trace") + handler = LogQuillHandler(logger) + stdlib_logger = _make_stdlib_logger(handler) + + stdlib_logger.warning("retrying request") + + assert len(sink.records) == 1 + assert sink.records[0]["level"] == "WARN" + assert sink.records[0]["message"] == "retrying request" + + +def test_level_mapping_matches_contract_names() -> None: + sink = CollectingTransport() + logger = Logger("app.test", transports=[sink], level="trace") + handler = LogQuillHandler(logger) + stdlib_logger = _make_stdlib_logger(handler) + + stdlib_logger.debug("d") + stdlib_logger.info("i") + stdlib_logger.warning("w") + stdlib_logger.error("e") + stdlib_logger.critical("c") + + levels = [r["level"] for r in sink.records] + assert levels == ["DEBUG", "INFO", "WARN", "ERROR", "FATAL"] + + +def test_extra_fields_land_in_meta() -> None: + sink = CollectingTransport() + logger = Logger("app.test", transports=[sink], level="trace") + handler = LogQuillHandler(logger) + stdlib_logger = _make_stdlib_logger(handler) + + stdlib_logger.info("processed", extra={"user_id": 42}) + + assert sink.records[0]["meta"]["user_id"] == 42 + + +def test_exc_info_becomes_formatted_stack() -> None: + sink = CollectingTransport() + logger = Logger("app.test", transports=[sink], level="trace") + handler = LogQuillHandler(logger) + stdlib_logger = _make_stdlib_logger(handler) + + try: + raise ValueError("boom") + except ValueError: + stdlib_logger.exception("failed") + + assert "ValueError: boom" in sink.records[0]["meta"]["stack"] + + +def test_logquill_level_filtering_still_applies() -> None: + sink = CollectingTransport() + logger = Logger("app.test", transports=[sink], level="error") + handler = LogQuillHandler(logger) + stdlib_logger = _make_stdlib_logger(handler) + + stdlib_logger.warning("dropped by logquill's own level") + stdlib_logger.error("kept") + + assert len(sink.records) == 1 + assert sink.records[0]["message"] == "kept" diff --git a/tests/test_plugins/test_rate_limit_plugin.py b/tests/test_plugins/test_rate_limit_plugin.py new file mode 100644 index 0000000..7caeedd --- /dev/null +++ b/tests/test_plugins/test_rate_limit_plugin.py @@ -0,0 +1,64 @@ +from __future__ import annotations + +import pytest + +from logquill.logger import Logger +from logquill.plugins.rate_limit_plugin import RateLimitPlugin + + +def test_allows_up_to_max_records_per_window() -> None: + logger = Logger("app.test", plugins=[RateLimitPlugin(2, 60.0)]) + + assert logger.info("a") is not None + assert logger.info("b") is not None + assert logger.info("c") is None + + +def test_different_levels_have_independent_windows_by_default() -> None: + logger = Logger("app.test", plugins=[RateLimitPlugin(1, 60.0)]) + + assert logger.info("a") is not None + assert logger.info("b") is None + assert logger.error("c") is not None + + +def test_window_resets_after_per_seconds_elapses() -> None: + now = [0.0] + logger = Logger("app.test", plugins=[RateLimitPlugin(1, 10.0, clock=lambda: now[0])]) + + assert logger.info("a") is not None + assert logger.info("b") is None + + now[0] = 10.0 + assert logger.info("c") is not None + + +def test_custom_key_func_groups_by_message() -> None: + plugin = RateLimitPlugin(1, 60.0, key_func=lambda record: record["message"]) + logger = Logger("app.test", plugins=[plugin]) + + assert logger.info("retry") is not None + assert logger.info("retry") is None + assert logger.info("other") is not None + + +def test_max_keys_evicts_oldest_key() -> None: + plugin = RateLimitPlugin(1, 60.0, key_func=lambda record: record["message"], max_keys=2) + logger = Logger("app.test", plugins=[plugin]) + + assert logger.info("k1") is not None + assert logger.info("k2") is not None + assert logger.info("k3") is not None # evicts k1's window + + # k1 was evicted, so it's treated as a fresh key and allowed again. + assert logger.info("k1") is not None + + +def test_invalid_max_records_raises() -> None: + with pytest.raises(ValueError): + RateLimitPlugin(0, 60.0) + + +def test_invalid_per_seconds_raises() -> None: + with pytest.raises(ValueError): + RateLimitPlugin(1, 0.0)