Skip to content

Structured Logging for Async Services

In a thread-per-request service, consecutive log lines usually belong to the same request. In an async service they almost never do: a thousand requests interleave on one thread, so log.info("fetching user") is a line with no owner. The fix is to bind the request's identity into contextvars once, at the boundary, and let every line inherit it — verified below, three concurrent requests produced three cleanly separated sets of fields with no leakage. The second problem is more specific to asyncio: logging is synchronous I/O, and a slow sink blocks the loop. Writing 50 lines to a handler taking 2 ms each produced 103 ms of loop lag; the same lines through a QueueHandler produced 1 ms.

Prerequisites

How log context follows a request 5 stages from bind once to clear on exit. How log context follows a request bind once request id and tenant handlers just log nothing to pass down tasks inherit a copy at creation rebinding is local the parent is safe clear on exit or the next one inherits Verified: three concurrent requests produced three distinct, non-overlapping context sets.

1. Emit events with fields, not sentences

A structured log line is an event name plus key-value pairs:

structlog.configure(
    processors=[
        structlog.contextvars.merge_contextvars,       # request context, automatically
        structlog.processors.add_log_level,
        structlog.processors.TimeStamper(fmt="iso", utc=True),
        structlog.processors.JSONRenderer(),
    ],
    cache_logger_on_first_use=True,
)
log = structlog.get_logger()

log.info("order_created", order_id=order.id, amount_cents=order.total, tenant=tenant)

Which produces one JSON object per line. The event name — order_created — stays stable while the fields change, so alerts and dashboards can be built on it; an f-string message changes whenever someone rewords it.

The cost is not a consideration: 4.04 µs per line for structlog's JSON renderer against 3.94 µs for stdlib logging writing plain text. Structure is effectively free, and searching order_id="123" instead of grepping a regex over prose is the entire return.

Verify: every line parses as JSON and carries an event name you could alert on.

Message strings or structured events? 2 columns contrasting f-string messages, structured events. Message strings or structured events? f-string messages human-first grep works, queries do not fields must be parsed back out no stable event name context repeated at every call site structured events machine-first query by field, not by regex context bound once per request a stable event name to alert on 4.04 µs per line, measured The cost is the same: structlog JSON measured 4.04 µs against 3.94 µs for plain stdlib text.

2. Bind the request context once

contextvars is what makes this work under concurrency: each task gets its own copy, so bound fields follow the logical request rather than the thread.

async def middleware(scope, receive, send):
    structlog.contextvars.bind_contextvars(
        request_id=scope["headers"].get("x-request-id", uuid4().hex),
        path=scope["path"],
        tenant=tenant_from(scope),
    )
    try:
        await app(scope, receive, send)
    finally:
        structlog.contextvars.clear_contextvars()      # or the next request inherits it

Verified with three concurrent requests: six log lines, three distinct (request_id, user) pairs, no mixing. A child task created inside a request inherits the context, and rebinding inside that child does not affect the parent — also verified, which is exactly the isolation you want.

The clear_contextvars() in the finally matters in servers that reuse a task per connection, where a leftover binding would attach one request's identity to the next.

Verify: two concurrent requests never produce a line carrying the other's identifiers.

3. Keep the sink off the event loop

This is the asyncio-specific trap. logging writes synchronously in the calling thread, so the cost of the sink — a file on a network mount, syslog, a log-shipping agent, a container runtime under load — lands on the event loop:

50 log lines to a 2 ms blocking handler -> peak loop lag 103 ms
the same 50 lines through a QueueHandler  -> peak loop lag   1 ms

QueueHandler plus QueueListener moves the actual writing to a background thread:

log_queue: queue.SimpleQueue = queue.SimpleQueue()
listener = logging.handlers.QueueListener(log_queue, *real_handlers)
listener.start()
logging.getLogger().handlers = [logging.handlers.QueueHandler(log_queue)]

Start the listener before the loop and stop it during shutdown so buffered records are flushed. The same reasoning applies to any per-line work: a processor that serialises large objects, resolves hostnames or formats tracebacks runs on the loop for every line it touches.

Writing to stdout in a container is usually fast — but "usually" is doing a lot of work when the runtime's log pipeline is backed up, which is exactly when you are logging the most.

Verify: loop lag does not correlate with log volume.

What a slow log sink does to the event loop 2 bars comparing direct handler, 2 ms per line with the others. What a slow log sink does to the event loop direct handler, 2 ms per line 103 ms peak lag via QueueHandler 1 ms peak lag Same 50 lines and the same slow sink; only the handoff differs. Logging is synchronous I/O on the loop unless you deliberately move it off.

4. Carry the trace id, and log outcomes

Logs and traces are only useful together when they share identifiers:

span = trace.get_current_span().get_span_context()
structlog.contextvars.bind_contextvars(
    trace_id=format(span.trace_id, "032x"),
    span_id=format(span.span_id, "016x"),
)

With that binding, a slow trace leads to its log lines in one query, and a suspicious log line leads to the trace that produced it.

Log outcomes with durations rather than progress:

log.info("upstream_call", target="billing", duration_ms=round(elapsed * 1000, 1),
         status=response.status_code, attempt=attempt)

A line per outcome, with a measured duration, is what makes "which dependency was slow" answerable from logs alone. A line per step — "calling billing", "called billing" — doubles the volume and answers nothing that a duration field does not.

Verify: every external call produces exactly one line with a duration and an outcome.

What every log line should carry A grid of 5 rows by 2 columns. What every log line should carry field source why request_id / job_id bound once per request groups the lines of one unit of work trace_id, span_id the current span jumps from a slow trace to its logs tenant, user id bound with the request high cardinality is fine here event, level, outcome the call site a stable string you can search duration_ms measured, not guessed the line that explains a slow trace Bind the context once per request; individual calls add only what is specific to them.

5. Control volume before it controls you

Logging is the one observability signal with no natural cap, and an async service can emit a great deal of it. Four habits keep it manageable:

  • One line per unit of work, not per step. Bind context; log outcomes.
  • Sample the routine. Health checks and hot successful paths can be sampled at 1%; errors never are.
  • Rate-limit repetitive errors. A dependency failing 5,000 times a second should produce a handful of lines and a counter, not 5,000 lines — the logging itself becomes the overload, as noted in load shedding.
  • Never log secrets or payloads. Add a processor that redacts known-sensitive keys rather than trusting every call site.
def redact(logger, method, event_dict):
    for key in ("password", "token", "authorization", "card_number"):
        if key in event_dict:
            event_dict[key] = "***"
    return event_dict

A processor is the right place because it applies to every line, including the ones written by libraries and by code added next year.

Verify: log volume per request is a small constant, and a secret-scanning test finds nothing.

Verification

Logging is production-ready when:

  • Lines are structured events with stable names and typed fields.
  • Request context is bound once and cleared at the boundary.
  • Concurrent requests never mix fields, verified under load.
  • The sink cannot block the loop, via QueueHandler or an equally fast destination.
  • Trace ids are present, joining logs to traces.
  • Volume is bounded by sampling and rate limiting, with redaction applied centrally.

Pitfalls & edge cases

  • Forgetting clear_contextvars. One request's identity leaks into the next on a reused task.
  • Logging inside a tight loop. Per-iteration lines are the fastest way to turn logging into the bottleneck.
  • logging.basicConfig plus a library's own handlers. Duplicate lines in two formats; configure the root logger once.
  • Expensive processors. Anything doing I/O or heavy serialisation runs on the loop for every line.
  • exc_info on ExceptionGroups. Use the group-aware approach from logging ExceptionGroups, or you lose every sub-exception.
  • Unbounded field values. A 2 MB response body in a log line will be truncated somewhere you do not control.

Frequently Asked Questions

How do I keep log context per request in an async service?

Bind it into contextvars at the boundary — structlog.contextvars.bind_contextvars(request_id=..., tenant=...) — and clear it in a finally. Each task gets its own copy, so concurrent requests never mix: verified, three concurrent requests produced three distinct, non-overlapping context sets.

Does structured logging slow down an async service?

Not measurably compared with plain logging: 4.04 µs per JSON line with structlog against 3.94 µs for stdlib plain text. What does slow a service down is the sink — 50 lines to a 2 ms handler produced 103 ms of event loop lag.

How do I stop logging from blocking the event loop?

Route records through logging.handlers.QueueHandler with a QueueListener writing in a background thread. The same 50 lines that caused 103 ms of loop lag caused 1 ms through a queue. Start the listener at startup and stop it during shutdown so buffered records flush.

Should log context be passed as function arguments?

No. Threading a request id through every signature is the problem contextvars solves, and it breaks as soon as a library sits between your layers. Bind at the boundary and let every line — including ones in code you did not write — inherit it.

How do I connect logs to traces?

Bind the current span's trace_id and span_id into the log context at the start of the request. Then a slow trace leads to its log lines in one query, and a suspicious log line leads back to the trace. Format them as hex strings so they match what the trace backend displays.