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