blackbull.server.access_log

blackbull.server.access_log

Per-request access-log helpers shared by the HTTP/1.1 and HTTP/2 paths.

AccessLogRecord dataclass

Per-request record populated in two phases.

Phase 1 (after parse): client_ip, method, path, http_version. Phase 2 (during send): status, response_bytes. For WebSocket sessions, close_code is captured on disconnect instead. Emitted as one INFO line on 'blackbull.access' after the response completes.

__str__()

Self-formatting message body. emit_access_log hands the record to logger.info as the message so this — and the format() string build it wraps — runs on the logging listener thread, not the event loop. Cached because several sink handlers may format the same record.

finalize()

Snapshot the duration at completion so a later (deferred) format() reports the request's real duration rather than duration + the time the record waited in the logging queue. Idempotent; returns self.

from_conn(conn) classmethod

Build directly from a :class:~blackbull.connection.Connection so the self-hosted actor never materializes the ASGI scope just to record the access line.

mark(name)

Capture wall + CPU clocks for name. No-op when phase tracing is disabled, so callers don't need to guard themselves.

phase_summary()

Format the phase deltas as a→b=Wus|Cus a→b=....

close_record(record)

Finish a request's record and emit it. A no-op when there is none.

Paired with :func:open_record, so a caller that opened a record does not also have to remember the final mark or repeat the is not None guard at every dispatch exit.

close_ws_record(record, close_code)

Finish a WebSocket session's record and emit it. A no-op when there is none — a session that never opened a record (no consumer, per :func:request_record_needed) must not crash its close path.

A session is not a request dispatch: it has no dispatch_done phase, and what it reports instead is the close code the peer or the server ended on. Separate from :func:close_record for that reason, so neither protocol actor has to know which terminal field belongs to which shape.

disconnect_events_observed(aggregator)

Whether the disconnect-detecting receive wrapper is observed.

The wrapper (a per-request closure) exists to (a) emit request_disconnected and (b) mark_disconnected so request_completed can suppress itself on a dropped request. With neither listener present nothing observes either effect, so the actor dispatches the raw receive directly and saves the closure. Body-level disconnect detection (conn.body() → ClientDisconnected) is independent of this wrapper and unaffected.

emit_access_log(record)

Emit record on the access logger if INFO is enabled.

The isEnabledFor gate matters: record.as_extra() is evaluated before logger.info decides to discard the call. Profiling at -R 5000 with BB_ACCESS_LOG=0 showed these calls still costing ~1.2% of CPU. Peers (uvicorn / granian / daphne) skip the work entirely when access logging is disabled; gating here matches that behaviour.

The record itself is the message (it is self-formatting via __str__), so the expensive format() string build is deferred to the logging listener thread instead of running on the event loop. finalize() snapshots the duration first so that deferred format still reports the request's real duration, not duration + queue latency. The structured extra fields stay eager — they are the documented public access-log API (guide.md §14; tests/integration/test_access_log.py).

When async logging is active and the access logger has not been customised, the record is enqueued directly onto the listener queue via :func:~blackbull.logger.enqueue_access_log (O4), which bypasses logging.Logger._log — ~93% of the loop-side emit cost lives in that stdlib machinery. The fast path is skipped (and the standard synchronous logger.info path used) when async logging is off or the user has attached their own handlers/filters to blackbull.access — those would be bypassed by a direct enqueue, so we defer to the full path to keep the documented "extend the access log via a custom handler/filter" pattern working (see docs/guide/logging.md).

open_record(conn, aggregator, loop_start=None)

Start a request's access-log record, or None if nothing reads it.

The one place that answers "does this request need a record, and if so what does a fresh one look like". Both protocol actors call it; neither decides the gate, builds the record, or knows that conn.state is where it is published.

loop_start seeds the phase trace with the keep-alive loop's entry timestamps, which only the H/1 actor has to give.

The record is always built from the Connection, never from an ASGI scope: the actor has the parsed Connection on every lane, and on the BB_FORCE_ASGI_SCOPE lane the emitted scope shares conn.state by identity — so the app's rebuilt Connection reads back the same record. That sharing is the contract BlackBull._dispatch relies on to source request_completed's wire fields.

request_record_needed(aggregator)

Whether the per-request :class:AccessLogRecord will be consumed.

The record (and the conn.state['access_log'] write it forces, plus the emit at request end) exists only for three consumers: the access log (blackbull.access at INFO), phase tracing, and the request_completed event's wire fields. When none is active the record is dead weight on every request — a per-request allocation the v0.60.0 Connection graph makes more costly under concurrency (extra live objects for the cyclic GC to scan) — so the actor skips building it. Consumers already tolerate its absence: the sender guards if self._log_record is not None and request_completed reads conn.state.get('access_log') with '-'/0 placeholders.

start_record(conn)

Build and publish a record unconditionally.

For the paths whose consumer analysis is not the per-request one: a WebSocket session's record spans the connection and carries close_code, and a pushed response needs one for the sender's inline capture. Both want a record regardless of what :func:request_record_needed says about ordinary requests.