Skip to content

v1.4.0

Choose a tag to compare

@kidoz kidoz released this 25 Sep 08:12
· 26 commits to main since this release

structguru v1.4.0

A correctness, security, and resilience release, from a deep review of v1.3.1 that turned up about fifty defects — each now pinned by a regression test that fails against the previous build. A forked child could hang forever logging to stdout; secrets reached log lines through exception locals, message placeholders, mapping keys, and Celery headers; callable sinks could be called from two threads at once, lose records during a reconfiguration, or be shut off while they were still delivering. Free-threaded CPython 3.14t gets its own wheels. The minor version reflects a handful of behavior changes that align structguru with loguru or close a silent failure — read them before you upgrade.

Behavior changes

  • logger.remove(handler_id) raises for an id that names no sink. An unknown or already-removed id raises ValueError, and a non-integer TypeError, with loguru's messages. Handler ids are now process-wide, so any Logger removes a sink added through another; a sink added through Logger(name=...) previously could not be removed through logger at all, and a mistyped id was ignored silently.

  • The message argument is positional-only, as in loguru, and so is self on bind() and contextualize(). logger.info("login", message=..., self=...) now logs message and self as fields instead of raising TypeError; passing the message itself by keyword, logger.info(message="login"), now raises TypeError.

  • logger.add(handler) leaves your handler alone. It used to set the handler's level to 0 and its formatter to %(message)s for good, changing its output for every other logger it was attached to, even after remove(). The handler now keeps both, its own formatter wraps the rendered line, and only add(level=...) gates what the sink receives. add(level=...) accepts integers and raises ValueError for an unknown level, like configure(), instead of warning and falling back to INFO.

  • A record rejected by a closed writer reaches no other destination. During reconfiguration or shutdown the synchronous stream_sink still received a record the native writer had already rejected. The stream, callable sinks, and Sentry now all follow the writer's outcome, and the rejection is counted in lifecycle_metrics() as before.

  • Console output escapes more and drops less. Quoted values escape " and \, keys containing spaces, =, quotes, or backslashes are quoted, and U+2028, U+2029, and bidirectional controls are escaped everywhere, so a request-controlled key or value can no longer imitate another field or start a new line. Floats use the JSON renderer's text, a formatted exception follows as an indented block like the stack, and user service and stack fields are shown instead of dropped. Ordinary string fields render exactly as before.

    before: 2026-09-25T08:00:00.000000Z [INFO    ] login  user="bob"  admin="true"  ratio=1
    after:  2026-09-25T08:00:00.000000Z [INFO    ] login  user="bob\"  admin=\"true"  ratio=1.0
    
  • Stdout is written straight to file descriptor 1 on Unix, one write per record with no user-space buffer, and keeps following fd 1 after a later dup2(). A closed stdout now counts as sink_errors instead of silently counting every record as written.

  • Integration timing. Flask and Django log a streamed response's summary when its body finishes, so with Werkzeug's test client the Flask summary appears after get_data() or close(). The ASGI duration_ms stops when the final response body is sent, not after Starlette background tasks.

Features

  • Free-threaded CPython 3.14t wheels for Linux x86_64, macOS arm64, and Windows x64. pip never selects an abi3 wheel on a free-threaded interpreter, so pip install structguru on 3.14t compiled the sdist and needed a Rust toolchain.

  • writer_metrics()["callable_errors"] counts exceptions raised by callable sinks, which used to be discarded without a trace; the first failure and every 1000th also emit a UserWarning from the delivery thread.

  • Numeric levels in the environment. LOG_LEVEL=10 or STRUCTGURU_LEVEL=25 is a threshold instead of an import-time error.

Fixes

Redaction

  • Exception locals no longer leak secrets through repr(). With exception_include_locals=True a local was redacted only when its own name was sensitive, so creds={"password": ...}, a dataclass with a password field, headers={"Authorization": ...}, or a bound Logger was written as its plain repr(). Values under a sensitive key are now redacted at any depth inside mappings, sequences, sets, named tuples, dataclasses, SimpleNamespace, and argparse.Namespace, without calling those containers' own __repr__. sensitive_patterns also see each local's whole rendering before it is cut to exception_max_local_repr; a secret straddling the cut used to escape its pattern half-disclosed.

    # before: "creds": "{'password': 'hunter2'}"
    # after:  "creds": "{'password': [REDACTED]}"
  • Message placeholders are redacted. logger.info("login token={token}", token=...) interpolated the token into the message — and into Sentry — while logger.info("login", token=...) was redacted. A placeholder that names a sensitive key, including attribute and index paths such as {creds[password]}, is now interpolated as [REDACTED], and a mapping, sequence, dataclass, or namespace a placeholder interpolates renders with its sensitive values redacted. The check adds roughly 0.1 µs to a formatted call; calls without arguments skip it.

  • sensitive_patterns cover mapping keys and integers. Patterns ran over string values only, so an e-mail address used as a key, or a card number passed as an int, was written verbatim. They now match every key at every depth and each integer's decimal digits; a matching integer is emitted as the redacted string, and keys that become identical are written once.

  • ASGI credential headers are redacted and bounded. extract_headers bound header names verbatim, so x-api-key, x-auth-token, proxy-authorization, and set-cookie were logged in clear while authorization and cookie were redacted, and a header of any size was copied into every log line of the request. Credential headers are now redacted, values must be printable UTF-8, and they are truncated at 256 characters.

  • Celery headers no longer carry unredacted context. Every bound value — a password included — was copied into the message headers in clear. Header values are now redacted with the runtime's keys, converted to transport-safe types, and bounded (see Integrations for the publish failure this also fixes).

Reliability

  • A forked child no longer hangs with target="stdout". The stdout sink wrote through Rust's std::io::stdout(), whose process-wide lock the parent's writer thread could be holding at fork(); the child's respawned writer then blocked on it forever, and with it flush(), interpreter exit, and — once the queue filled — every logging call. A child forked while the parent was blocked writing to a slowly drained pipe hung 5 times out of 5, and 2 times out of 60 with stdout redirected to a file; both now complete every time, on macOS and on glibc.

  • Callable sinks are called by one thread, in log order. logger.add(), configure(), and update() started a new delivery generation before the old one drained, so a backlogged sink was called from two threads at once and saw records out of order — 53 inversions in 260 records in one run. A new generation now accepts records at once but delivers only after its predecessors finish, and logger.add() no longer replaces the generation or waits for its backlog, which took 3.5 s for 300 queued 10 ms deliveries and never returned behind a stuck sink.

  • Records accepted just before a reconfiguration reach callable sinks and Sentry. Delivery was decided by whether the runtime still used the same writer rather than by the enqueue result. With four threads logging and another looping update(), 15 to 20 of 80,000 records reached the file but never the logger.add() sink, and nothing counted them.

  • A slow sink that keeps delivering is no longer abandoned. The stall check counted only released producers, which settle a whole 64-record batch at a time, so with the default 10-second limit any sink slower than about 156 ms per record was declared stuck and disabled, with 1,045 records counted as lost. Completed deliveries now count as progress. The same limit now also bounds configure(), update(), and logger.remove(), which could wait forever behind a stuck sink, and concurrent flushes report an abandoned generation once.

  • The rotating file sink resolves a relative file_path once, so a later os.chdir() no longer splits the log; retries a lock-file wait interrupted by a signal instead of dropping the record; reopens a log that logrotate renamed or deleted even with rotation disabled; and no longer writes records it counted as failed from a retained buffer once the disk recovers.

  • A forked child whose writer cannot restart disables logging with one line on stderr, instead of keeping the dead writer, dropping records uncounted, and hanging in flush().

  • Logging never raises for its own diagnostics or arguments. Under -W error the queue-full, sink-error, abandonment, and formatting warnings raised out of the logging call; they now go to sys.unraisablehook. A message whose str() raises, or an argument whose __format__ raises, falls back to a placeholder or the raw template.

Correctness

  • Leaving contextualize() in a different context — a generator iterated from a thread pool, an async generator finalized by the garbage collector — raised ValueError. It now restores the entry context when the current context still holds the block's own mapping, and leaves any other context, such as another request's, untouched.

  • Standard-library records are filtered by their real level. A bridged level-25 record was judged as INFO: dropped under level=25, sampled away under sample_max_level="INFO", and skipped by an add(level=25) sink. Bridged records also keep record.created as their timestamp, so records replayed through a QueueListener keep their original time.

  • @logger.catch() used as a decorator logged under contextlib or asyncio.events; it now uses the decorated function's module.

  • The exit drain is registered at import, so an atexit handler registered before an explicit configure() can still log.

  • Value conversion. A lone surrogate renders as one U+FFFD instead of three, and a surrogate pair split across code points as its character; int and float subclasses such as numpy.float64 render by value instead of <unsupported: T>; keys that render alike, such as 1 next to "1", no longer produce duplicate JSON keys.

  • Brace formatting matches str.format. }} is unescaped whenever arguments are given, logger.exception("{{x}}") renders like logger.error("{{x}}"), nested format-spec fields ({x:{width}}) are consumed, and an {exc_info} placeholder no longer drops the exception. Templates longer than 512 characters are no longer cached: 300 dynamic 100 KB messages kept 30 MB alive.

  • Smaller fixes. A field named event no longer changes which MetricProcessor metrics fire; stack_info keeps the frames of user modules named structguru_*; an infinite stall timeout no longer panics in flush() and at exit; callable_dropped survives logger.add().

Integrations

  • Celery context propagation could make task.delay() raise: a bound Path, set, or custom object failed JSON serialization, and a UUID failed py-amqp's header encoding. A failed export now drops the header instead of failing the publish. A failed first setup_celery_logging() call no longer disables later ones, and a second call with different options warns instead of being ignored.

  • Flask and Django bind the request context while a streamed body is produced — its chunks logged with request_id=None — and log the summary when the body finishes, with the full duration. Flask's hook runs before every other before_request hook, so an auth hook that returns 401 still gets a summary; a propagated exception logs Request failed; and a failing after_request hook no longer produces two summaries. Django's console logging config includes the service name.

  • ASGI restores the context of outer middleware instead of wiping it, echoes the request id under the configured request_id_header, and logs KeyboardInterrupt and exception groups as failures instead of Request completed.

  • gRPC matches a mixed-case request_id_key and accepts binary -bin keys, which failed every RPC. Sentry events are captured on sentry-sdk 1.x, which has no new_scope(). requests logs the URL it actually sends, including params=. The SQLAlchemy log-all recipe no longer logs every query as a slow-query warning.

Docs

  • The redaction reference lists exactly what key and pattern redaction cover — names, values, integers, placeholders, exception locals, and what the metric hook sees — and the context-propagation guide explains that an async generator needs aclose() or contextlib.aclosing() to unbind its context.

Test coverage

  • 225 new Python test cases and 16 new Rust tests since v1.3.1 — 957 Python tests and 95 Rust tests in total, with line coverage at 93%. The golden parity suites compare against a real structlog and orjson pipeline again; they had drifted into comparing the native renderer with itself. The fixes were verified on macOS, the fork, lifecycle, and dispatch suites also on glibc in a Linux container, and the native suites on free-threaded 3.14t.