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 (Sprint 80 Tier-2) 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=....

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() and (formerly) record.format() are 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).

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.