From 485dde74b8eef727696b37c00194f3205bf131e0 Mon Sep 17 00:00:00 2001 From: Nikhil Arora Date: Sat, 17 Oct 2026 14:35:18 +0530 Subject: [PATCH] Improve thread safety and formatter performance Lock shared transport buffers and file writes for concurrent logging, add an optional orjson JSON backend, and cache bounded OptLogger views. Update documentation, benchmarks, and CI for free-threaded Python; switch new releases to FSL-1.1-MIT. --- .github/workflows/ci.yml | 48 ++++++++ CHANGELOG.md | 47 ++++++++ LICENSE | 105 ++++++++++++++-- README.md | 113 ++++++++++++++++++ benchmarks/measure.py | 10 ++ logquill/core/logger.py | 23 +++- logquill/formatters/json_formatter.py | 51 +++++++- logquill/transports/batching_transport.py | 32 +++-- logquill/transports/file_transport.py | 30 +++-- logquill/transports/http_transport.py | 27 +++-- pyproject.toml | 13 +- tests/conftest.py | 10 ++ tests/test_formatter.py | 38 ++++++ tests/test_opt.py | 52 ++++++++ .../test_batching_transport.py | 28 +++++ 15 files changed, 586 insertions(+), 41 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 08835d6..7137736 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -44,3 +44,51 @@ jobs: - run: pip install -e ".[dev]" - run: pytest benchmarks + + # Free-threaded (PEP 703, no-GIL) builds — the audit this phase requires + # for the worker/transport locking that backs `async_dispatch=False` + # (multiple application threads sharing one `Logger` and its transports). + # 3.13t and 3.14t get different dependency installs, not the same `dev` + # extras as the matrix above, because the free-threaded packaging + # ecosystem is still catching up as of this writing: + # - `orjson` (the `fast` extra) refuses to build for *any* free-threaded + # interpreter — its own build script rejects it outright, not just a + # missing-wheel gap. Skipped on both versions here. + # - `hypothesis`'s native extension, `jsonschema`'s `rpds-py`, and + # `twine`'s dependency chain are all PyO3-based and PyO3 itself + # refuses to target a free-threaded build below 3.14 — so on 3.13t + # only a pure-Python subset (`pytest`/`pytest-asyncio`/`pytest-cov`) + # installs at all. `tests/conftest.py` turns a missing `hypothesis` + # into a clean `collect_ignore_glob` for the property-based suites + # rather than a collection error. 3.14t has real `hypothesis` wheels + # and runs the full suite, `fast` aside. + # - `ruff`/`mypy` aren't re-run here — they don't depend on the + # interpreter's threading model, and the matrix job above already + # covers them on 3.13/3.14. + free-threaded: + runs-on: ubuntu-latest + strategy: + fail-fast: false + matrix: + python-version: ["3.13t", "3.14t"] + + steps: + - uses: actions/checkout@v7 + + - uses: actions/setup-python@v7 + with: + python-version: ${{ matrix.python-version }} + + - run: python -c "import sys; assert not sys._is_gil_enabled(), 'GIL unexpectedly enabled'" + + - name: Install dependencies + run: | + if [ "${{ matrix.python-version }}" = "3.13t" ]; then + pip install -e ".[http,apprise,otel]" "pytest>=8.0" "pytest-asyncio>=0.24" "pytest-cov>=5.0" + else + pip install -e ".[dev,http,apprise,otel]" + fi + + - run: pytest + + - run: pytest benchmarks diff --git a/CHANGELOG.md b/CHANGELOG.md index 3c05aaa..f431925 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,53 @@ All notable changes to this project are documented in this file. ## Unreleased +- **Breaking: license change.** Starting with this release, `logquill` is + source-available under [FSL-1.1-MIT](LICENSE) (the Functional Source + License, MIT Future variant) instead of MIT. Free for internal use, + non-commercial education/research, and professional services you provide + to a licensee; a commercial product or service that competes with + logquill itself needs a separate commercial license from the author. Each + version converts to plain MIT two years after that version's own release. + **This is not retroactive** — 1.0.0 and every earlier release already on + PyPI remain MIT, unaffected. See the [License](README.md#license) section + of the README for the full explanation. +- Performance and platform hardening: + - `JSONFormatter(backend="orjson")` (`pip install logquill[fast]`) swaps + the stdlib `json` module for the Rust-backed `orjson` library — same + compact output, less CPU per call under sustained logging volume. + `orjson` is imported lazily and only if you ask for it; zero required + dependencies is unaffected. `orjson` doesn't currently support + free-threaded Python at all (its own build script refuses it, not a + missing-wheel gap), so `backend="json"` is what a free-threaded + interpreter gets regardless of what's installed. + - Thread-safety audit and fix: `BatchingTransport` (the shared base for + every SQL/NoSQL/queue/cloud transport), `HTTPTransport`, and + `FileTransport` now lock around their internal buffer/file-handle + mutation. Previously, a `Logger(async_dispatch=False)` (the default) + shared across application threads could race on these — two threads + passing the batch-size check before either flushed, or a rotation + closing a file handle out from under a concurrent write — silently + losing or duplicating records. Confirmed as a real, reproducible loss + (not just theoretical) under free-threaded Python before the fix, and + confirmed fixed after, via a 16-thread burst test. `AsyncWorker` was + already correctly locked (a `threading.Condition`-guarded queue) and + needed no change. + - `Logger.opt(lazy=..., depth=...)` now caches the returned `OptLogger` + per `(lazy, depth)` combination instead of allocating a fresh one on + every call — the common idiom is calling it inline on every log call + (`logger.opt(lazy=True).debug(...)`), so this removes a wrapper-object + allocation from that path. Bounded at 32 cached combinations per + `Logger` so a caller computing `depth` dynamically can't grow it + without limit. A new benchmark metric (`peak_bytes_filtered_opt_call`) + guards the filtered-and-deferred path specifically. + - The full test suite and the memory-budget benchmark suite now run in + CI on free-threaded Python (`3.13t` and `3.14t`, PEP 703) alongside the + existing GIL-enabled matrix. `hypothesis`'s native extension doesn't + yet ship (or build) wheels for free-threaded Python below 3.14 — an + upstream PyO3 constraint — so `tests/conftest.py` turns a missing + `hypothesis` into a clean skip of the property-based suites rather + than a collection error, and the `3.13t` CI job installs a smaller + dependency set accordingly. - Internal reorganization: the top-level modules that had grown past a single implementation each are now grouped into themed subpackages — `core/` (`logger`, `levels`, `records`, `context`, `exceptions`, diff --git a/LICENSE b/LICENSE index 812faa2..d08fc70 100644 --- a/LICENSE +++ b/LICENSE @@ -1,13 +1,102 @@ -MIT License +# Functional Source License, Version 1.1, MIT Future License -Copyright (c) 2026 Nikhil Arora +## Abbreviation -Permission is hereby granted, free of charge, to any person obtaining a copy -of this software and associated documentation files (the "Software"), to deal -in the Software without restriction, including without limitation the rights -to use, copy, modify, merge, publish, distribute, sublicense, and/or sell -copies of the Software, and to permit persons to whom the Software is -furnished to do so, subject to the following conditions: +FSL-1.1-MIT + +## Notice + +Copyright 2026 Nikhil Arora + +## Terms and Conditions + +### Licensor ("We") + +The party offering the Software under these Terms and Conditions. + +### The Software + +The "Software" is each version of the software that we make available under +these Terms and Conditions, as indicated by our inclusion of these Terms and +Conditions with the Software. + +### License Grant + +Subject to your compliance with this License Grant and the Patents, +Redistribution and Trademark clauses below, we hereby grant you the right to +use, copy, modify, create derivative works, publicly perform, publicly display +and redistribute the Software for any Permitted Purpose identified below. + +### Permitted Purpose + +A Permitted Purpose is any purpose other than a Competing Use. A Competing Use +means making the Software available to others in a commercial product or +service that: + +1. substitutes for the Software; + +2. substitutes for any other product or service we offer using the Software + that exists as of the date we make the Software available; or + +3. offers the same or substantially similar functionality as the Software. + +Permitted Purposes specifically include using the Software: + +1. for your internal use and access; + +2. for non-commercial education; + +3. for non-commercial research; and + +4. in connection with professional services that you provide to a licensee + using the Software in accordance with these Terms and Conditions. + +### Patents + +To the extent your use for a Permitted Purpose would necessarily infringe our +patents, the license grant above includes a license under our patents. If you +make a claim against any party that the Software infringes or contributes to +the infringement of any patent, then your patent license to the Software ends +immediately. + +### Redistribution + +The Terms and Conditions apply to all copies, modifications and derivatives of +the Software. + +If you redistribute any copies, modifications or derivatives of the Software, +you must include a copy of or a link to these Terms and Conditions and not +remove any copyright notices provided in or with the Software. + +### Disclaimer + +THE SOFTWARE IS PROVIDED "AS IS" AND WITHOUT WARRANTIES OF ANY KIND, EXPRESS OR +IMPLIED, INCLUDING WITHOUT LIMITATION WARRANTIES OF FITNESS FOR A PARTICULAR +PURPOSE, MERCHANTABILITY, TITLE OR NON-INFRINGEMENT. + +IN NO EVENT WILL WE HAVE ANY LIABILITY TO YOU ARISING OUT OF OR RELATED TO THE +SOFTWARE, INCLUDING INDIRECT, SPECIAL, INCIDENTAL OR CONSEQUENTIAL DAMAGES, +EVEN IF WE HAVE BEEN INFORMED OF THEIR POSSIBILITY IN ADVANCE. + +### Trademarks + +Except for displaying the License Details and identifying us as the origin of +the Software, you have no right under these Terms and Conditions to use our +trademarks, trade names, service marks or product names. + +## Grant of Future License + +We hereby irrevocably grant you an additional license to use the Software under +the MIT license that is effective on the second anniversary of the date we make +the Software available. On or after that date, you may use the Software under +the MIT license, in which case the following will apply: + +Permission is hereby granted, free of charge, to any person obtaining a copy of +this software and associated documentation files (the "Software"), to deal in +the Software without restriction, including without limitation the rights to +use, copy, modify, merge, publish, distribute, sublicense, and/or sell copies +of the Software, and to permit persons to whom the Software is furnished to do +so, subject to the following conditions: The above copyright notice and this permission notice shall be included in all copies or substantial portions of the Software. diff --git a/README.md b/README.md index 60e850f..8126cfc 100644 --- a/README.md +++ b/README.md @@ -13,6 +13,14 @@ Sibling to [`logquill` on npm](https://www.npmjs.com/package/logquill) (`logquill-js`) — same log record shape, same level names, one mental model across a Python + Node stack. +**License note:** starting with 2.0.0, new releases are source-available +under the [Functional Source License](#license) (FSL-1.1-MIT), not MIT. +Free for nearly everyone — internal use, non-commercial work, building a +product or service that isn't a logging framework — paid only if you're +building a competing logging/observability offering. Versions 1.0.0 and +earlier stay MIT forever; this doesn't change anything about those. See +[License](#license) below for what that actually means. + Status: pre-release, under active development. The core `Logger`, level filtering, transports, the plugin pipeline, and agentic/harness tracing are implemented; non-blocking async dispatch is not yet — see `CHANGELOG.md` @@ -40,6 +48,7 @@ for what's landed so far. - **Runtime intelligence** — `FlightRecorderPlugin` ships a run's buffered DEBUG trail only if it errors; `RunSummaryPlugin` emits one record with a run's total tokens/cost/tool calls/retries/errors; `AdaptiveSamplingPlugin` always keeps errors and slow spans while capping ordinary traffic to a bytes-per-second budget; `install_signal_level_handler`/`LevelFileWatcher`/`LevelEnvWatcher` change a logger's level without a restart — see [Runtime level control](#runtime-level-control) - **Metrics bridge** — `MetricsPlugin` turns ERROR/FATAL records into a counter and any `meta.duration_ms` into a histogram, tagged by logger; ships with `OTelMetricsBackend` (default), `StatsDBackend`, and `PrometheusPushgatewayBackend` — see [Metrics bridge](#metrics-bridge) - **Graph transports** — `Neo4jTransport`, `FalkorDBTransport`, `NeptuneTransport` write every record as a node and `parent_span_id` as a `PARENT_OF` edge, so a run's span tree is a Cypher traversal away with zero manual graph-writing code; one shared `BaseGraphTransport` means switching backends only means swapping the transport — see [Graph transports](#graph-transports) +- **A faster JSON backend, and free-threaded Python support** — `JSONFormatter(backend="orjson")` (`pip install logquill[fast]`) for less CPU per call under sustained volume; the worker and every batching transport lock around their shared buffers so a `Logger` used from multiple application threads is safe under both the GIL and free-threaded (PEP 703) builds — tested on 3.13t and 3.14t in CI — see [Thread safety](#thread-safety) ## Install @@ -260,6 +269,28 @@ In a config file, name the formatter as a string in the transport's `options`: `{"type": "console", "options": {"formatter": "text"}}` (`"json"`, `"text"` or `"logfmt"`). To write your own, implement `format(record) -> str`. +#### A faster JSON backend + +`JSONFormatter(backend="orjson")` (`pip install logquill[fast]`) swaps the +stdlib `json` module for the Rust-backed `orjson` library — same compact +output, meaningfully less CPU per call under sustained logging volume. +Zero required dependencies is unaffected: the default stays `backend="json"`, +and `orjson` is only imported if you ask for it, raising an actionable +`ImportError` right away if it isn't installed, not on the first `format()` +call: + +```python +from logquill import ConsoleTransport, JSONFormatter, Logger + +transport = ConsoleTransport(formatter=JSONFormatter(backend="orjson")) +logger = Logger("app.api", transports=[transport]) +logger.info("user signed up", user_id=42) +``` + +`orjson` doesn't currently support free-threaded Python builds (3.13t/3.14t) +— that's an `orjson` limitation, not a LogQuill one, so `backend="json"` +(the default) is what those interpreters use regardless. + ### SQL, NoSQL, message queue, and cloud-native transports Every transport below shares one design: records are **always batched** @@ -1463,6 +1494,43 @@ nothing catches the signal. A `SIGTERM` handler or `preStop` hook that calls `logger.close(timeout=...)` closes that gap the same way `with_lambda` closes it for a serverless freeze. +### Thread safety + +A single `Logger` (and the transports/plugins it was built with) is safe to +call from multiple application threads at once, with `async_dispatch=True` +or without it: + +- With `async_dispatch=False` (the default), every `.info()`/`.error()`/... + call dispatches to transports on the caller's own thread — so if several + threads share one `Logger`, they can genuinely run a transport's `write()` + concurrently. `BatchingTransport` (the shared base for the SQL/NoSQL/ + queue/cloud transports), `HTTPTransport`, and `FileTransport` each lock + around their internal buffer/file-handle mutation for exactly this reason. +- With `async_dispatch=True`, every transport write and `after_log` hook + already runs serialized on the single `AsyncWorker` background thread + (itself built on a `threading.Condition`-guarded queue), so this is moot + for those two things specifically — but `before_log` plugin hooks still + run on the calling thread either way (they can filter/transform the + record, so a later hook needs to see the result in order), which matters + for the next point regardless of `async_dispatch`. +- A plugin with its own internal counter — `RunPlugin`'s step counter, + `SamplingPlugin`/`AdaptiveSamplingPlugin`'s rate state, + `TamperEvidentPlugin`'s hash chain — mutates that state in `before_log`, + always on the calling thread. Sharing one plugin instance (via one + `Logger`, or via `.child()`) across multiple threads that log + concurrently isn't guarded by a lock today; `TamperEvidentPlugin` + specifically depends on its hash chain being appended to in the same + order records are meant to chain in, so a multi-threaded audit logger is + the case to be most careful with. Give each thread (or each request) its + own `.child()` logger if you need per-thread isolation, which is also the + simpler mental model regardless of this caveat. + +Verified under both the GIL and free-threaded (PEP 703, `python3.13t`/ +`python3.14t`) builds in CI: the full test suite and the memory-budget +benchmarks (see [Development](#development)) run on both, plus a dedicated +burst test hammering one `BatchingTransport` from 16 threads at once and +checking every record arrived exactly once. + ## Context propagation, exception capture & the stdlib bridge `bind_context()` binds request-scoped values for a `with` block — every @@ -1851,8 +1919,53 @@ pre-commit install ruff check . mypy logquill pytest +pytest benchmarks # memory budgets for the logging hot path ``` +CI also runs the full suite and the benchmarks on free-threaded Python +(`3.13t`/`3.14t`) — see [Thread safety](#thread-safety). `hypothesis` and +`orjson` (the `fast` extra) don't currently build for `3.13t`, an upstream +PyO3/orjson limitation, not a LogQuill one, so that job installs a smaller +dependency set there; `tests/conftest.py` turns a missing `hypothesis` into +a clean skip of the property-based suites rather than a collection error. + See [CONTRIBUTING.md](CONTRIBUTING.md) for the PR workflow, the [Code of Conduct](CODE_OF_CONDUCT.md) for community standards, and [SECURITY.md](.github/SECURITY.md) for how to report a vulnerability. + +## License + +**Versions 1.0.0 and earlier are MIT**, full stop — already published, and +relicensing later code doesn't and can't change the terms of what's already +out there. If you depend on one of those versions, nothing here affects you. + +**Version 2.0.0 and later are [FSL-1.1-MIT](LICENSE)** (the [Functional +Source License](https://fsl.software), MIT Future variant). In plain terms: + +- You can use, modify, self-host, and redistribute logquill for **almost + anything** — your own app or service, internal tooling, a client project, + non-commercial education or research, or as part of professional services + you provide to someone else — with no payment or extra permission needed. +- The one thing you can't do without a separate commercial license is use + logquill to build a **competing product or service**: one that substitutes + for logquill itself, substitutes for another product/service built on + logquill, or offers substantially the same functionality. That's aimed at + "take this, repackage it, sell it as your own logging/observability + product" — not at ordinary use of a logging library inside whatever you're + actually building. +- **Each version converts to plain MIT two years after that version's own + release date.** So 2.0.0 becomes MIT two years after 2.0.0 ships, + independent of whatever the latest version is by then — the restriction + only ever applies to recent releases, never indefinitely. +- Redistributing logquill (modified or not) requires keeping the copyright + notice and a copy of (or link to) these terms — that's the "credit" + obligation the license itself carries. + +Need a commercial license (or just have questions about whether your use +case needs one)? Open an issue, or reach out to the author directly. + +This is a source-available license, not an OSI-approved open-source one — +drafted from the official FSL template and not customized beyond filling in +the licensor/year, but also not reviewed by a lawyer on either side of a +specific deal. If a commercial license matters to your business, have your +own counsel look at the exact terms before you rely on them. diff --git a/benchmarks/measure.py b/benchmarks/measure.py index 19758a8..9dcb479 100644 --- a/benchmarks/measure.py +++ b/benchmarks/measure.py @@ -33,6 +33,13 @@ "retained_blocks_per_call": 0.05, # transient bytes at the peak of one call: level-filtered (never builds a record) "peak_bytes_filtered_call": 1_000, + # the `logger.opt(lazy=True).debug(...)` idiom, filtered out — close to + # `peak_bytes_filtered_call` since `Logger.opt` caches the `OptLogger` + # per (lazy, depth) instead of allocating one fresh every call; mainly + # guards against something heavier creeping onto this path (e.g. a lazy + # value getting resolved before the level check), not the ~100-byte + # difference the cache itself makes + "peak_bytes_filtered_opt_call": 1_200, # ... a call through no plugins, and through a realistic plugin stack "peak_bytes_plain_call": 12_000, "peak_bytes_plugin_call": 14_000, @@ -151,6 +158,9 @@ def measure_all() -> dict[str, float]: return { "retained_blocks_per_call": retained_blocks_per_call(plain), "peak_bytes_filtered_call": peak_bytes_per_call(lambda: filtered.info("x", **_META)), + "peak_bytes_filtered_opt_call": peak_bytes_per_call( + lambda: filtered.opt(lazy=True).info("x", **_META) + ), "peak_bytes_plain_call": peak_bytes_per_call(lambda: plain.info("x", **_META)), "peak_bytes_plugin_call": peak_bytes_per_call(lambda: with_plugins.info("x", **_META)), "peak_bytes_stalled_burst": peak_bytes_stalled_burst(), diff --git a/logquill/core/logger.py b/logquill/core/logger.py index 822b5f1..7788a39 100644 --- a/logquill/core/logger.py +++ b/logquill/core/logger.py @@ -95,6 +95,7 @@ def __init__( else None ) self._retries = RetryTracker() + self._opt_cache: dict[tuple[bool, int | None], OptLogger] = {} if flush_at_exit: shutdown.register(self) @@ -187,13 +188,33 @@ def close(self, timeout: float | None = 5.0) -> None: transport.close() shutdown.mark_closed(transport) + #: Caps `_opt_cache` (see `opt()`) so a caller that computes `depth` + #: dynamically per call — an unusual pattern, but not one worth trusting + #: not to happen — can't grow it without bound; past this, `opt()` just + #: stops caching and returns a fresh, uncached `OptLogger` each time. + _OPT_CACHE_MAX = 32 + def opt(self, *, lazy: bool = False, depth: int | None = None) -> OptLogger: """A view of this logger with per-call options — `lazy=True` to defer expensive `meta` values until the record is really emitted, `depth=N` to report the caller `N` frames up the stack. See `OptLogger`. + + The common idiom is calling this inline on every log call + (`logger.opt(lazy=True).debug(...)`), so the returned `OptLogger` — + itself immutable once built — is cached per `(lazy, depth)` + combination instead of allocated fresh every time; a benign race + between two threads caching the same combination at once just + produces one short-lived extra instance, never a wrong one. """ - return OptLogger(self, lazy=lazy, depth=depth) + key = (lazy, depth) + cached = self._opt_cache.get(key) + if cached is not None: + return cached + view = OptLogger(self, lazy=lazy, depth=depth) + if len(self._opt_cache) < self._OPT_CACHE_MAX: + self._opt_cache[key] = view + return view def _track_retries(self, level: Level, meta: dict[str, Any]) -> None: """Stamp `meta.retry_count` on a tool `.action()` that reopens a call diff --git a/logquill/formatters/json_formatter.py b/logquill/formatters/json_formatter.py index 84210cd..e1ebfe0 100644 --- a/logquill/formatters/json_formatter.py +++ b/logquill/formatters/json_formatter.py @@ -1,14 +1,61 @@ from __future__ import annotations import json +from typing import Callable, Literal from logquill.core.records import LogRecord +_Dumps = Callable[[LogRecord], str] + + +def _json_dumps(record: LogRecord) -> str: + return json.dumps(record, separators=(",", ":"), default=str) + + +def _make_orjson_dumps() -> _Dumps: + try: + import orjson + except ImportError as exc: + raise ImportError( + "JSONFormatter(backend='orjson') requires the optional `orjson` " + "dependency — install with `pip install logquill[fast]`." + ) from exc + + def dumps(record: LogRecord) -> str: + # Explicit annotation, not inlined: when `orjson` has no stubs on + # mypy's search path (the pre-commit hook's bare environment + # doesn't install it), `orjson.dumps(...)` types as `Any` and + # returning `.decode(...)` on it directly would trip + # `--strict`'s `warn_return_any` — annotating `encoded: bytes` + # tells mypy to trust that type from here on instead. + encoded: bytes = orjson.dumps(record, default=str) + return encoded.decode("utf-8") + + return dumps + class JSONFormatter: - """Serializes a record to the canonical JSON line shape.""" + """Serializes a record to the canonical JSON line shape. + + `backend="json"` (default) uses the stdlib — zero dependencies, same as + every other core component. `backend="orjson"` (`pip install + logquill[fast]`) uses the Rust-backed `orjson` library instead, which is + meaningfully faster on the hot path under sustained logging volume; the + output is the same compact JSON either way, so switching backends never + changes what a transport receives. Raises `ImportError` right away, at + construction, if `orjson` isn't installed — not on the first `format()` + call. + """ + + def __init__(self, *, backend: Literal["json", "orjson"] = "json") -> None: + if backend == "json": + self._dumps: _Dumps = _json_dumps + elif backend == "orjson": + self._dumps = _make_orjson_dumps() + else: + raise ValueError(f"JSONFormatter: backend must be 'json' or 'orjson', got {backend!r}") def format(self, record: LogRecord) -> str: """Serializes `record` to a single compact JSON line; non-JSON-native values fall back to `str()` rather than raising.""" - return json.dumps(record, separators=(",", ":"), default=str) + return self._dumps(record) diff --git a/logquill/transports/batching_transport.py b/logquill/transports/batching_transport.py index c95b6af..4628c24 100644 --- a/logquill/transports/batching_transport.py +++ b/logquill/transports/batching_transport.py @@ -2,6 +2,7 @@ import json import logging +import threading from abc import abstractmethod from typing import Generic, Sequence, TypeVar, cast @@ -24,6 +25,16 @@ class BatchingTransport(Transport, Generic[T]): hit, checked after every `write()`. `_send_batch` is never called with an empty batch, and a failing send is caught and logged rather than propagated — a slow or down sink can never crash the caller's process. + + `write()`/`flush()` take a lock around the buffer swap: with + `Logger(async_dispatch=False)` (the default), transport writes run on + whatever thread called the logger, so one transport instance shared by a + `Logger` used from multiple application threads would otherwise race on + `_buffer`/`_buffer_bytes` — two threads could both pass the `max_records` + check before either flushes, or a `flush()` on one thread could swap the + buffer out from under an `append()` on another. The lock is held only + around the in-memory buffer mutation, never around `_send_batch` itself, + so a slow or blocked sink still can't stall a concurrent `write()`. """ def __init__( @@ -41,6 +52,7 @@ def __init__( self.max_bytes = max_bytes self._buffer: list[T] = [] self._buffer_bytes = 0 + self._buffer_lock = threading.Lock() def _to_item(self, formatted: str, record: LogRecord) -> T: return cast(T, record) @@ -52,9 +64,14 @@ def write(self, formatted: str, record: LogRecord) -> None: """Buffers `record` (converted via `_to_item`) and triggers a `flush()` as soon as either `max_records` or `max_bytes` is reached.""" item = self._to_item(formatted, record) - self._buffer.append(item) - self._buffer_bytes += self._size_of(item) - if len(self._buffer) >= self.max_records or self._buffer_bytes >= self.max_bytes: + size = self._size_of(item) + with self._buffer_lock: + self._buffer.append(item) + self._buffer_bytes += size + should_flush = ( + len(self._buffer) >= self.max_records or self._buffer_bytes >= self.max_bytes + ) + if should_flush: self.flush() def flush(self) -> None: @@ -62,10 +79,11 @@ def flush(self) -> None: the buffer first so a failing send doesn't retry the same batch on the next flush; a send failure is caught and logged, never raised to the caller. No-op if nothing is buffered.""" - if not self._buffer: - return - batch, self._buffer = self._buffer, [] - self._buffer_bytes = 0 + with self._buffer_lock: + if not self._buffer: + return + batch, self._buffer = self._buffer, [] + self._buffer_bytes = 0 try: self._send_batch(batch) except Exception: diff --git a/logquill/transports/file_transport.py b/logquill/transports/file_transport.py index bab6f3f..abb8677 100644 --- a/logquill/transports/file_transport.py +++ b/logquill/transports/file_transport.py @@ -1,5 +1,6 @@ from __future__ import annotations +import threading from pathlib import Path from typing import Any, BinaryIO, TextIO, cast @@ -39,6 +40,12 @@ class FileTransport(Transport): files are append-only ciphertext, one Fernet token per line — not human-readable, and not `FileTransport`'s job to decrypt back; do that with the same key via `Fernet.decrypt()` per line when reading. + + `write()` locks around the write-and-maybe-rotate sequence: with + `async_dispatch=False` (the default), a `Logger` shared across + application threads would otherwise let `_rotate()` close and reopen + the file handle while another thread's `write()` is still using the old + one — not just interleaved lines, but a write to an already-closed file. """ def __init__( @@ -63,6 +70,7 @@ def __init__( self._fernet: Any = _load_fernet(encrypt_key) if encrypt_key is not None else None self.path.parent.mkdir(parents=True, exist_ok=True) self._file: TextIO | BinaryIO = self._open() + self._write_lock = threading.Lock() def _open(self) -> TextIO | BinaryIO: if self._fernet is not None: @@ -73,15 +81,16 @@ def write(self, formatted: str, record: LogRecord) -> None: """Appends `formatted` as one line (encrypted first if `encrypt_key` was set), flushes to disk immediately, and rotates if `max_bytes` has been reached.""" - if self._fernet is not None: - cast(BinaryIO, self._file).write( - self._fernet.encrypt(formatted.encode("utf-8")) + b"\n" - ) - else: - cast(TextIO, self._file).write(formatted + "\n") - self._file.flush() - if 0 < self.max_bytes <= self._file.tell(): - self._rotate() + with self._write_lock: + if self._fernet is not None: + cast(BinaryIO, self._file).write( + self._fernet.encrypt(formatted.encode("utf-8")) + b"\n" + ) + else: + cast(TextIO, self._file).write(formatted + "\n") + self._file.flush() + if 0 < self.max_bytes <= self._file.tell(): + self._rotate() def _rotate(self) -> None: self._file.close() @@ -101,4 +110,5 @@ def _rotate(self) -> None: def close(self) -> None: """Closes the underlying file handle.""" - self._file.close() + with self._write_lock: + self._file.close() diff --git a/logquill/transports/http_transport.py b/logquill/transports/http_transport.py index 1be5add..c82f1a6 100644 --- a/logquill/transports/http_transport.py +++ b/logquill/transports/http_transport.py @@ -1,6 +1,7 @@ from __future__ import annotations import logging +import threading import urllib.request from typing import Callable, Literal, Sequence @@ -42,6 +43,11 @@ class HTTPTransport(Transport): that batch is dropped, never raised into the code that logged; the transport keeps accepting records, so a down endpoint costs completeness, not the process. + + `write()`/`flush()` lock around the buffer swap, the same as + `BatchingTransport` — with `async_dispatch=False` (the default), a + `Logger` shared across application threads would otherwise race on the + buffer here too. """ def __init__( @@ -78,23 +84,30 @@ def __init__( ) self._batch: list[str] = [] self._batch_bytes = 0 + self._batch_lock = threading.Lock() def write(self, formatted: str, record: LogRecord) -> None: """Buffers `formatted` and triggers a `flush()` once `batch_size` records or `max_bytes` bytes are buffered.""" - self._batch.append(formatted) - self._batch_bytes += len(formatted.encode("utf-8", errors="replace")) - if len(self._batch) >= self.batch_size or self._batch_bytes >= self.max_bytes: + size = len(formatted.encode("utf-8", errors="replace")) + with self._batch_lock: + self._batch.append(formatted) + self._batch_bytes += size + should_flush = ( + len(self._batch) >= self.batch_size or self._batch_bytes >= self.max_bytes + ) + if should_flush: self.flush() def flush(self) -> None: """Sends whatever is currently buffered via the sender, clearing the buffer first. No-op if nothing is buffered. A failed send is logged, not raised.""" - if not self._batch: - return - batch, self._batch = self._batch, [] - self._batch_bytes = 0 + with self._batch_lock: + if not self._batch: + return + batch, self._batch = self._batch, [] + self._batch_bytes = 0 try: self._sender(self.url, batch) except Exception: diff --git a/pyproject.toml b/pyproject.toml index c7615a1..07984d1 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -7,7 +7,7 @@ name = "logquill" version = "1.0.0" description = "A structured, leveled logging framework with pluggable transports and a plugin pipeline." readme = "README.md" -license = "MIT" +license = "FSL-1.1-MIT" requires-python = ">=3.10" authors = [{ name = "Nikhil Arora" }] keywords = [ @@ -23,7 +23,7 @@ keywords = [ classifiers = [ "Development Status :: 5 - Production/Stable", "Intended Audience :: Developers", - "License :: OSI Approved :: MIT License", + "License :: Other/Proprietary License", "Operating System :: OS Independent", "Programming Language :: Python :: 3", "Programming Language :: Python :: 3.10", @@ -68,6 +68,7 @@ crewai = ["crewai>=1.0"] llamaindex = ["llama-index-core>=0.12"] autogen = ["autogen-core>=0.6"] yaml = ["PyYAML>=6.0"] +fast = ["orjson>=3.10"] dev = [ "ruff>=0.6", "mypy>=1.11", @@ -152,11 +153,11 @@ files = ["logquill"] module = "logquill.transports.file_transport" warn_unused_ignores = false -# `apprise` and `aiohttp` are optional dependencies that a bare type-check -# environment (the pre-commit hook) doesn't install, so their imports have to -# resolve the same way whether or not they're present. +# `apprise`, `aiohttp`, and `orjson` are optional dependencies that a bare +# type-check environment (the pre-commit hook) doesn't install, so their +# imports have to resolve the same way whether or not they're present. [[tool.mypy.overrides]] -module = ["apprise", "aiohttp"] +module = ["apprise", "aiohttp", "orjson"] ignore_missing_imports = true # OpenTelemetry is optional too, and is imported lazily; treating it as untyped diff --git a/tests/conftest.py b/tests/conftest.py index a90c3f3..255253e 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -6,6 +6,16 @@ from logquill.runtime import toggle +try: + import hypothesis # noqa: F401 +except ImportError: + # `hypothesis`'s native extension doesn't ship (or build) wheels for + # free-threaded Python below 3.14 — not a LogQuill limitation, an + # upstream one. Skip the property-based suites outright rather than + # failing collection on an environment where the dependency simply + # can't install. + collect_ignore_glob = ["test_*_properties.py"] + @pytest.fixture(autouse=True) def _reset_enable_disable_rules() -> Iterator[None]: diff --git a/tests/test_formatter.py b/tests/test_formatter.py index ace09a7..7eb160d 100644 --- a/tests/test_formatter.py +++ b/tests/test_formatter.py @@ -1,4 +1,7 @@ import json +import sys + +import pytest from logquill.core.logger import Logger from logquill.formatter import JSONFormatter @@ -13,3 +16,38 @@ def test_json_formatter_round_trips_record() -> None: parsed = json.loads(formatted) assert parsed == record + + +def test_an_unknown_backend_raises_right_away() -> None: + with pytest.raises(ValueError, match="backend must be 'json' or 'orjson'"): + JSONFormatter(backend="yaml") # type: ignore[arg-type] + + +def test_orjson_backend_without_orjson_installed_raises_an_actionable_error( + monkeypatch: pytest.MonkeyPatch, +) -> None: + monkeypatch.setitem(sys.modules, "orjson", None) + + with pytest.raises(ImportError, match=r"pip install logquill\[fast\]"): + JSONFormatter(backend="orjson") + + +def test_orjson_backend_produces_the_same_json_as_the_stdlib_backend() -> None: + pytest.importorskip("orjson") + logger = Logger("app.test") + record = logger.info("hello", user_id=42, tag=object()) + assert record is not None + + stdlib_formatted = JSONFormatter(backend="json").format(record) + orjson_formatted = JSONFormatter(backend="orjson").format(record) + + assert json.loads(orjson_formatted) == json.loads(stdlib_formatted) + + +def test_orjson_backend_raises_right_away_not_on_first_format( + monkeypatch: pytest.MonkeyPatch, +) -> None: + monkeypatch.setitem(sys.modules, "orjson", None) + + with pytest.raises(ImportError): + JSONFormatter(backend="orjson") diff --git a/tests/test_opt.py b/tests/test_opt.py index 41520d0..2378028 100644 --- a/tests/test_opt.py +++ b/tests/test_opt.py @@ -1,5 +1,7 @@ from __future__ import annotations +from typing import Callable + import pytest from logquill import Level, Logger @@ -155,3 +157,53 @@ def test_negative_depth_is_rejected() -> None: with pytest.raises(ValueError, match="depth"): logger.opt(depth=-1) + + +def test_opt_with_the_same_options_returns_the_same_cached_instance() -> None: + """The common idiom is `logger.opt(lazy=True).debug(...)` called inline + on every log call — this proves it doesn't allocate a fresh `OptLogger` + each time.""" + logger, _ = _logger() + + first = logger.opt(lazy=True, depth=1) + second = logger.opt(lazy=True, depth=1) + + assert first is second + + +def test_opt_with_different_options_returns_different_instances() -> None: + logger, _ = _logger() + + assert logger.opt(lazy=True) is not logger.opt(lazy=False) + assert logger.opt(depth=0) is not logger.opt(depth=1) + assert logger.opt(depth=None) is not logger.opt(depth=0) + + +def test_a_cached_opt_view_still_behaves_correctly_across_repeated_use() -> None: + logger, sink = _logger(level="INFO") + calls: list[int] = [] + + def expensive(value: int) -> Callable[[], int]: + def compute() -> int: + calls.append(value) + return value + + return compute + + view = logger.opt(lazy=True) + assert view.debug("filtered out", dump=expensive(1)) is None + assert calls == [] + + record = view.info("emitted", dump=expensive(2)) + assert record is not None + assert calls == [2] + assert sink.records[0]["meta"]["dump"] == 2 + + +def test_the_opt_cache_is_bounded() -> None: + logger, _ = _logger() + + for depth in range(64): + logger.opt(depth=depth) + + assert len(logger._opt_cache) <= logger._OPT_CACHE_MAX diff --git a/tests/test_transports/test_batching_transport.py b/tests/test_transports/test_batching_transport.py index 3a7a96e..64d5ff2 100644 --- a/tests/test_transports/test_batching_transport.py +++ b/tests/test_transports/test_batching_transport.py @@ -1,5 +1,6 @@ from __future__ import annotations +import threading from typing import Sequence from logquill.core.levels import Level @@ -72,3 +73,30 @@ def test_buffer_is_cleared_before_send_avoiding_reentrant_double_send() -> None: assert len(transport.sent_batches) == 2 assert transport.sent_batches[0][0]["message"] == "first" assert transport.sent_batches[1][0]["message"] == "second" + + +def test_concurrent_writes_from_many_threads_lose_or_duplicate_nothing() -> None: + """`async_dispatch=False` runs transport writes on the caller's own + thread, so a transport shared by a `Logger` used from multiple + application threads sees concurrent `write()` calls directly — this is + the scenario `_buffer_lock` exists for.""" + transport = CollectingBatchTransport(max_records=7, max_bytes=10_000_000) + writes_per_thread = 200 + thread_count = 16 + + def hammer(thread_index: int) -> None: + for i in range(writes_per_thread): + transport.write("x", _record(f"t{thread_index}-{i}")) + + threads = [threading.Thread(target=hammer, args=(i,)) for i in range(thread_count)] + for t in threads: + t.start() + for t in threads: + t.join() + transport.flush() + + seen = [record["message"] for batch in transport.sent_batches for record in batch] + assert len(seen) == writes_per_thread * thread_count + assert len(set(seen)) == len(seen) # no duplicates + assert transport._buffer == [] + assert transport._buffer_bytes == 0