Skip to content

v1.3.0

Choose a tag to compare

View all tags
@kidoz kidoz released this 17 Sep 17:08
· 64 commits to main since this release
v1.3.0
8d4858b

structguru v1.3.0

A performance and resilience release. The whole logging path — merging bound fields, call keywords and contextvars, redacting, rendering, and enqueuing — now runs in one native call driven by a RuntimeConfig compiled at configuration time, and callable-sink dispatch moved into the extension as well; measured against v1.2.3 on the same machine, a simple logger.info() is about 20% faster, bind() and brace formatting about a third, and redaction about 38%. Settings makes configuration reusable and defines exactly how the environment layers into configure(). Four resilience defects found by fault injection are fixed, including an os.fork() that stalled for tens of seconds in a prefork server under logging load. Nothing was removed from the public API, but three behavior changes are worth reading before you upgrade.

Behavior changes

  • configure() now layers the environment. Defaults are applied first, then the supported STRUCTGURU_* variables, then your explicit keywords. Previously explicit keywords and environment values did not compose in a defined order. Pass configure(Settings(...)) to ignore the environment entirely. configure() still replaces prior settings; the new update() keeps the options you omit.

  • Invalid levels and invalid environment values now fail loudly. Native configuration and set_level() reject unknown level names, booleans, and negative integers with ValueError instead of coercing them, and non-negative integer thresholds are accepted. An invalid value in a selected STRUCTGURU_* variable fails at import rather than starting with logging silently misconfigured, unless autoconfiguration is disabled.

  • Importing without the native extension fails at import. The Rust renderer has been the only logging path since v1.0, and the level table now comes from the core as well, so a missing structguru._rust raises the existing "requires its native extension" RuntimeError immediately instead of at first use. is_available() is kept for compatibility and is always True once the package has imported.

Performance

  • One native call per record. The writer merges bound fields, call keywords, and contextvars, redacts, renders, and enqueues in a single call, using a configuration compiled when you call configure() — no per-record configuration is marshalled across the boundary, and the console format is fused exactly like JSON. Output is byte-for-byte unchanged.

    benchmark v1.2.3 v1.3.0
    logger.info("Hello world") 2.75 µs 2.19 µs
    brace formatting 2.79 µs 1.80 µs
    bind() 2.64 µs 1.80 µs
    redaction 3.97 µs 2.47 µs
    contextvars merge 3.46 µs 2.31 µs
    blocking enqueue 0.18 µs 0.10 µs

    Three runs of the full suite per version on one machine, garbage collection disabled, deltas beyond run-to-run noise. Two isolated conversion micro-benchmarks moved the other way — _conversion_stats and _render_json_debug are 17% to 27% slower — which is the cost of snapshotting dictionary entries before a converter can mutate them, redacting logger and service metadata, and replacing unpaired surrogates. The end-to-end paths above already include it.

  • Callable-sink dispatch runs in the extension. The bounded queue, its worker thread, sink selection, delivery accounting, and deferred handler closes all moved to Rust, and the dispatcher is skipped entirely while no sink is registered. Caller cost with a sink configured drops by a third to a half. Lifecycle, backpressure, fork, and callback-reentrancy semantics are unchanged.

  • The rotating file sink stats instead of reopening. It no longer closes, reopens, and stats the log file before every record to notice a rotation by another process; it stats the path once and compares file identity with the handle it holds. With rotation enabled the writer thread handles 256 records in 0.63 ms instead of 5.08 ms, and a caller throttled by a full queue waits 2.6 µs per record instead of 21 µs.

  • The blocking enqueue only releases the GIL when the queue is actually full. Releasing it around every push forced a hand-off per record whenever another thread was runnable: four threads logging concurrently now spend 3.0 ms instead of 5.6 ms per 1,000 records, eight threads 6.0 ms instead of 10.5 ms.

  • configure(exception_carets=False) omits the PEP 657 position markers — the ~~~^^^ lines under each frame — from formatted tracebacks. CPython computes them per frame while formatting, and on 3.11+ they are most of the cost of logger.exception(): a 22-frame traceback formats in 92 µs instead of 475 µs. The output is exactly what CPython prints under PYTHONNODEBUGRANGES=1, including chained exceptions and exception groups. The default is unchanged.

Features

  • Settings is a frozen, validated configuration object with mapping and environment constructors, readable back through get_config() and adjustable through update().

    from structguru import Settings, configure, update

base = Settings(service="checkout", level="INFO", format="json")
configure(base)                      # ignores the environment
configure(Settings.from_env())       # explicit environment layering
update(level="DEBUG")                # keeps every other option, and in-flight delivery

    configure() keeps accepting its existing keywords through a typed wrapper, so no call site has to change. A level-only update() preserves the writer, buffered records, and rate-limit state rather than rebuilding them.

  • STRUCTGURU_LEVEL, STRUCTGURU_TARGET, STRUCTGURU_FORMAT, STRUCTGURU_SAMPLE_RATE, STRUCTGURU_RATE_LIMIT, and STRUCTGURU_AUTOCONFIGURE are read by autoconfiguration and by Settings.from_env(). The existing environment names remain supported.

  • lifecycle_metrics() reports the cumulative count of native deliveries rejected because their writer was closed. It survives reconfiguration and shutdown, starts fresh in a forked child, and is distinct from queue-full drops, sink errors, and filtered records.

Fixes

Four of these came from fault-injection experiments run against this release candidate; each one is now pinned by a regression test that fails against the previous build.

  • os.fork() no longer stalls while other threads are logging. The pre-fork drain calls flush(), and the native writer waited for its queue to be empty — a moment that never arrives when producers refill it faster than the sink drains it. In a prefork server with four logging threads and a file sink, fork() took 44 to 110 seconds in our measurements. A flush now waits only for the records enqueued before it was called, so its cost is bounded by the queue depth; the same experiment now returns in 0.29 s.

  • A callable sink that never returns no longer blocks shutdown() and interpreter exit forever. flush() and shutdown() give a stalled dispatch worker 10 seconds to make progress, then abandon the generation, warn with the number of undelivered records, and disable callable delivery until the next configure(). Records already handed to the stuck callback cannot be recovered, and the sink's own thread is left detached rather than killed — a timeout cannot safely terminate user code. If that callback ever does return, the abandoned worker winds down without starting another delivery or re-entering the interpreter.

  • The rate limiter's key table is capped. It keys on the formatted message, so a message that embeds an attempt number or an ID creates a new key per record and is never actually limited. One million such messages within a period grew the process by roughly 320 MB; the table now holds at most 8192 keys, sweeping stale buckets and then evicting the least recently seen, and the same workload costs 5.5 MB. Keys that are actively being limited are kept. The message-keyed behavior itself is unchanged and is now documented in configure().

  • A synchronous stream_sink whose write() raises is no longer silent. Failures are counted in writer_metrics()["stream_errors"] and warned about at a bounded rate. The failure is still contained and the record still reaches the native destinations, but lost stream copies are now visible.

  • Closing, reconfiguring, or shutting down in a forked child on Linux no longer panics with failed to join thread: Invalid argument. glibc reuses the parent's dead worker thread identity for the child's respawned worker, and releasing the abandoned parent writer detached that live thread; the stale handle is now leaked instead.

  • The stdlib bridge no longer deadlocks under callable-sink backpressure. It held its handler lock while waiting for queue space, so a sink callback that logged through logging could deadlock both sides. Handler filters, including replacement records on Python 3.12+, still apply.

  • A sink removed from inside a sink callback closes its handler only after the deliveries already queued for it have run. Closing at once left those deliveries writing to a closed handler: a FileHandler silently reopened its file and leaked the stream. The close is deferred to the worker that finishes the last delivery.

  • Queue overflow and closed-writer rejections are distinguished at enqueue time, so racing reconfiguration or shutdown cannot hide a rejection or mislabel it as a full queue. Shutdown drains callable deliveries before closing the writer so their nested logs finish, and interpreter exit clears the active runtime, so a later atexit handler sees disabled logging rather than a closed writer.

  • Redaction and text handling. Stack text is escaped and every continuation line indented for console output, with redaction still running first. Sensitive-key matching handles Unicode case variants, including nested fields. URL sanitization rejects URLs whose authority failed to parse — https:/user:pw@host/path, where urlsplit() leaves the credentials in the path — instead of logging them. Unpaired surrogates in messages, logger and service names, stack text, sampling and rate-limit keys, and field keys are rendered with U+FFFD instead of dropping the record.

  • Integrations. The Django JSON formatter includes a record's formatted exception and stack, so logger.exception() no longer loses the traceback; Django middleware clears request context when lazy user evaluation fails. The ASGI middleware logs Request cancelled without inventing a 500 status. Eager and nested Celery tasks restore caller context on success and failure. Sentry keeps a message when a field named event collides with it, and recognizes catch-level aliases. logger.add(level=...) and the stdlib bridge accept TRACE, SUCCESS, EXCEPTION, and FATAL like the rest of the library.

  • logger.catch(level="trace") filters at DEBUG severity, consistently with logger.trace(), for level filtering, sampling, and sink thresholds, in both the synchronous and coroutine decorators. logger.catch() also validates case-insensitive level names before execution and handles awaited coroutine exceptions.

  • The wheel no longer installs a stray top-level LICENSE file into site-packages. It ships in the wheel's dist-info/licenses/ directory and in the sdist, as before.

Docs

  • A Granian integration guide, covering the access-log routing that a bridge on the root logger does not capture, since Granian's granian.access logger has its own handler and does not propagate.

  • Configuration documentation for Settings, update(), get_config(), and the environment names, plus the API reference overview listing them. The is_available() entry now says what it means after the import change.

Test coverage

  • 222 new Python test cases and 12 new Rust tests since v1.2.3 — 730 Python tests and 79 Rust tests in total, with line coverage at 94%. The four resilience fixes are pinned by bounded-subprocess regression tests that were each verified to fail against a wheel built before the fix, and the release runs its gates on CPython 3.11 through 3.14 plus a free-threaded 3.14t job.
Assets 2
Loading