Logging

BlackBull uses three separate logger hierarchies, each with a distinct purpose:

Logger	Level	What it carries
blackbull.access	INFO	One record per completed HTTP/1.1 request or HTTP/2 stream
blackbull.caps	WARNING	One record per cap rejection (header sizes, timeouts, connection cap, WS frame cap, H/2 stream caps, compression in-flight, …)
blackbull (+ children)	DEBUG	Internal framework events (frame parsing, HPACK, routing decisions, TLS handshake)

Configure levels and handlers through Python logging. Importing the package does not install a sink; serving with BB_ASYNC_LOGGING=1 installs the default async stderr sink. Access output still depends on its INFO level and BB_ACCESS_LOG.

Access log — blackbull.access

For every completed HTTP/1.1 request or HTTP/2 stream the server emits one INFO record on the blackbull.access logger. Default format:

{client_ip} "{method} {path} HTTP/{version}" {status} {bytes} {duration}ms

Example:

203.0.113.42 "POST /tasks HTTP/1.1" 201 87 3ms

Request-derived values are escaped for the message line so one request is one line: non-printables and spaces become \uXXXX, and "/\ are backslash-escaped. The named fields below keep the raw values.

Enable to stdout the same way as any Python logger:

import logging

handler = logging.StreamHandler()
handler.setFormatter(logging.Formatter('%(asctime)s %(message)s'))
logging.getLogger('blackbull.access').addHandler(handler)
logging.getLogger('blackbull.access').setLevel(logging.INFO)

To a rotating file:

from logging.handlers import RotatingFileHandler

fh = RotatingFileHandler('access.log', maxBytes=10_000_000, backupCount=5)
fh.setFormatter(logging.Formatter('%(message)s'))
logging.getLogger('blackbull.access').addHandler(fh)
logging.getLogger('blackbull.access').setLevel(logging.INFO)

The record is emitted in a finally block after the response completes — even if the app raises an unhandled exception. When the app never sent a response, status is the literal '-'.

Named fields in the LogRecord

Every access log record carries the following named attributes, available in a custom logging.Formatter format string:

Attribute	Type	Example
%(client_ip)s	str	203.0.113.42
%(method)s	str	POST
%(path)s	str	/tasks
%(http_version)s	str	1.1
%(status)s	int or '-'	201
%(response_bytes)d	int	87
%(duration_ms).1f	float	3.4

Custom format (the fields are raw; %(message)s is the escaped line):

fmt = ('%(asctime)s %(client_ip)s "%(method)s %(path)s" '
       '%(status)s %(response_bytes)d %(duration_ms).0fms')
logging.getLogger('blackbull.access').handlers[0].setFormatter(
    logging.Formatter(fmt)
)

Disabling the access log

Set the level above INFO, or set the environment variable BB_ACCESS_LOG=0 to disable access-record formatting.

Built-in async logging sinks

With BB_ASYNC_LOGGING=1 (the default) BlackBull installs a QueueHandler on the blackbull logger so every log call from the event loop enqueues in O(1); a background QueueListener thread drains the queue and writes to a sink. You select the sink and format entirely with environment variables — no code:

Variable	Default	Effect
BB_LOG_FILE	(stderr)	Write to a file (append mode) instead of stderr.
BB_LOG_FORMAT	(plain)	json → one structured JSON object per line (the AccessLogRecord fields become top-level keys).
BB_SYSLOG_ADDR	(unset)	host:port → ship records via a UDP SysLogHandler.
BB_LOG_BATCH_SIZE	64	Coalescing width — records joined into one write()+flush().
BB_LOG_BATCH_TIMEOUT_MS	5	Max time a partial batch waits before flushing.

Async logging is batch logging. The stream/file sink always coalesces records into one write per batch — a per-record flush() is the dominant cost of a high-rate access log (one flush syscall per request, contending for the GIL with the event loop). BB_LOG_BATCH_SIZE tunes the coalescing width, not an on/off switch; the timeout bounds visibility latency at low rate. To force an immediate per-record flush, disable async logging (BB_ASYNC_LOGGING=0, the synchronous path).

Custom handlers and filters attached to blackbull.access are honored.

For the full list see environment variables.

Extending the access log record from middleware

The AccessLogRecord for the current request is stored at conn.state['access_log']. Middleware that runs before the handler can attach extra attributes:

import uuid

async def request_id_mw(conn, receive, send, call_next):
    req_id = uuid.uuid4().hex
    conn.state['request_id'] = req_id
    # Attach to the access log record so it appears in log output
    record = conn.state.get('access_log')
    if record:
        record.request_id = req_id   # arbitrary extra attribute
    await call_next(conn, receive, send)

A custom logging.Filter can then surface the attribute:

class AccessLogFilter(logging.Filter):
    def filter(self, record):
        record.request_id = getattr(record, 'request_id', '-')
        return True

handler = logging.StreamHandler()
handler.addFilter(AccessLogFilter())
handler.setFormatter(logging.Formatter(
    '%(message)s req_id=%(request_id)s'
))
logging.getLogger('blackbull.access').addHandler(handler)

Framework debug log — blackbull

Internal framework events (frame parsing, HPACK, routing decisions, TLS handshake) are logged on the blackbull logger and its children (blackbull.server.server, blackbull.protocol.frame, …) at DEBUG level.

Enable for development:

import logging

logging.basicConfig(level=logging.DEBUG)
# or target just the server layer:
logging.getLogger('blackbull.server').setLevel(logging.DEBUG)

This is separate from the access log so that production deployments can enable access logging without flooding logs with internal debug output.

@log decorator

The @log decorator from blackbull.logger annotates a function so that its call arguments are logged at DEBUG level using the caller module's logger:

from blackbull.logger import log

@log
async def my_fn(x, y):
    ...
# logs: my_fn((x_val, y_val), {}) at DEBUG level

Zero-overhead at non-DEBUG level. The check runs at decoration time (import), not on every call. When the module logger is not enabled for DEBUG at import time, the decorator returns the original function unwrapped — there is no extra call frame or level-check overhead in production.

The trade-off: setting the log level to DEBUG after modules have already been imported will not activate @log logging for already-decorated functions. Configure DEBUG level before importing framework modules, or restart the process.

The same applies to internal DEBUG logging

Internal request-path DEBUG traces also capture the level at import.

So configure DEBUG before importing blackbull if you want internal debug output:

import logging
logging.basicConfig(level=logging.DEBUG)   # before the import below

from blackbull import BlackBull

Raising the level afterwards still affects WARNING/ERROR and the access log, which are checked per call as usual; it will not switch on the per-request DEBUG traces. Those paths emit around twenty lines per request, so they are a development setting rather than something to enable on a running server.

Forwarding logs to a remote server

logging.Handler.emit() is synchronous. Calling a blocking HTTP request directly from emit would stall the asyncio event loop. The solution is the standard library's QueueHandler + QueueListener pair: the handler enqueues records in O(1) without blocking, and a background thread drains the queue and calls the real (blocking) HTTP handler.

A complete two-process example is provided in examples/LoggingExample/:

File	Role
web_server.py	BlackBull hello-world with JsonHTTPHandler + QueueListener
log_server.py	http.server that receives JSON records and inserts them into SQLite

Start order:

# Terminal 1
python examples/LoggingExample/log_server.py   # listens on :9000

# Terminal 2
python examples/LoggingExample/web_server.py   # listens on :8000

# Make some requests
curl http://localhost:8000/
curl http://localhost:8000/tasks

# Inspect the database
sqlite3 examples/LoggingExample/logs.db \
    "SELECT client_ip, method, path, status, duration_ms FROM access_logs;"

The shape of the wiring:

import queue, logging
from logging.handlers import QueueHandler, QueueListener

_log_queue    = queue.Queue(-1)          # unbounded
_json_handler = JsonHTTPHandler('localhost:9000')
_listener     = QueueListener(_log_queue, _json_handler,
                              respect_handler_level=True)

_access_logger = logging.getLogger('example.access')
_access_logger.addHandler(QueueHandler(_log_queue))
_access_logger.setLevel(logging.INFO)


@app.on_startup
async def start_log_listener():
    _listener.start()


@app.on_shutdown
async def stop_log_listener():
    _listener.stop()


@app.on('request_completed')
async def log_response(event):
    d = event.detail
    _access_logger.info('%s %s → %s (%.1f ms)',
                        d['method'], d['path'], d['status'], d['duration_ms'],
                        extra={'client_ip': d['client_ip'] or '-',
                               'method': d['method'], 'path': d['path'],
                               'status': d['status'],
                               'response_bytes': d['response_bytes'],
                               'duration_ms': d['duration_ms']})

QueueHandler.emit() puts the record in the queue and returns immediately. QueueListener runs in a daemon thread and calls JsonHTTPHandler.emit() there — the blocking HTTP call never touches the event-loop thread.

@app.on_startup / @app.on_shutdown tie the listener lifecycle to the server, so the background thread starts only when the server is ready and is flushed and joined cleanly before the process exits.

Cap-hit log — blackbull.caps

Every user-tunable resource cap in BlackBull emits one WARNING record on blackbull.caps when it fires. Coverage:

Cap (env var)	Where it fires
BB_MAX_CONNECTIONS	accept loop — a refusal (limit is the cap) or a pause in accepting (limit is slightly above the cap)
BB_HEADER_TIMEOUT	slowloris defence — headers didn't arrive in time
BB_HEADER_MAX_LINE	per-line header limit exceeded
BB_HEADER_MAX_TOTAL	HTTP/1.1 header block or HTTP/2 encoded/decoded field section exceeded; decoded requested is a lower bound (limit + 1)
BB_BODY_TIMEOUT	HTTP/1.1 body bytes didn't arrive in time; HTTP/2 uses its request deadline and body rate/size bounds
BB_MAX_BODY_SIZE	request body over the total cap (H/1.1 + H/2; requested is the declared length at head time, the running total mid-stream)
BB_MIN_BODY_RATE	body delivered below the minimum rate past the grace period — requested is the observed rate in bytes/second
BB_REQUEST_TIMEOUT	handler exceeded its request budget (HTTP/1.1 + HTTP/2)
BB_WRITE_TIMEOUT	drain stalled (slow-read peer)
BB_WS_MAX_FRAME_PAYLOAD	WebSocket frame declared length exceeded
BB_WS_MAX_MESSAGE_SIZE	WebSocket message over the total cap post-reassembly / post-inflation — requested is the size reached when the bound tripped, never the size the message would have become
BB_FRAME_RATE_LIMIT	A metered control frame exceeded its per-type budget (H/2 RST_STREAM — inbound or server-emitted — PING, SETTINGS, zero-length frames; WebSocket control frames). Logged as cap name frame_rate; protocol says which protocol
BB_MQTT_MAX_PACKET_SIZE	MQTT packet declared larger than the cap — requested is the declared size, since the payload is refused unread
BB_MQTT_MAX_QUEUED_MESSAGES	MQTT session backlog full while the client's Receive Maximum window was; scope_path carries the topic
BB_MQTT_MAX_RETAINED	MQTT retained publish to a new topic refused at the store cap; scope_path carries the topic
BB_H2_MAX_CONCURRENT_STREAMS	HTTP/2 stream-open guard tripped
BB_H2_WS_MAX_STREAMS_PER_CONNECTION	RFC 8441 WebSocket stream cap tripped
BB_COMPRESSION_MAX_INFLIGHT	Compression middleware bypassed (executor saturated)
BB_SOCKET_BACKLOG	An AF_UNIX listener's accept queue was full when accepting opened, so clients may have been refused during lifespan startup. Logged as cap name socket_backlog; requested is the number waiting, limit the kernel's effective backlog (an adopted fd's own, capped by net.core.somaxconn), and scope_path the listener's path (@name for an abstract socket). Linux only

Client bounds use the same records. A cap's refusal scope depends on the protocol:

Cap (env var)	HTTP/1.1	HTTP/2	WebSocket
BB_CLIENT_HEAD_MAX_TOTAL	the response head over the budget; the trailer section over the same one	the stream's field lines in aggregate; the encoded block reassembled across CONTINUATION	—
BB_CLIENT_HEAD_MAX_LINE	a status line, response field line, chunk-size line or trailer field line over the per-line rule	— no field line exists; the section is the unit	—
BB_CLIENT_HEAD_TIMEOUT	the response head did not arrive in time	the peer took the request and never began to answer — that stream is reset; or a field block opened and never finished with END_HEADERS — the connection ends	—
BB_CLIENT_BODY_TIMEOUT	one body read outlasted its deadline	no nonempty DATA progress for that stream inside the deadline	—
BB_CLIENT_BODY_MAX_TOTAL	a declared Content-Length over the cap, or the running total of a chunked or close-delimited body	the running total, checked before a DATA payload is held	—
BB_CLIENT_MIN_BODY_RATE	body arriving below the floor past the grace period — requested is the observed rate in bytes/second	DATA payload arriving below the floor; each stream is reset independently	—
BB_CLIENT_MAX_INTERIM_RESPONSES	too many 1xx responses before the final one	too many 1xx sections before the final one — one with no fields charges nothing to BB_CLIENT_HEAD_MAX_TOTAL	—
BB_CLIENT_RAW_QUEUE_DEPTH	— no raw-stream hatch	the raw-stream queue is full	—
BB_CLIENT_H2_MAX_FRAME_SIZE	— no frame	the declared frame length is over the cap	—
BB_CLIENT_H2_MAX_HEADER_LIST_SIZE	— no field section	the decoded field section is over the cap. requested is a lower bound, not the figure: hpack reports the limit it refused at and never the total it reached. A tight one — it charges each entry and compares immediately, so it raises on the entry that crosses and the section is provably just over the limit	—
BB_CLIENT_WRITE_TIMEOUT	client socket drain stalled; requested is the per-drain deadline	client socket drain or flow-control credit wait stalled; requested is the per-wait deadline	client socket drain stalled; requested is the per-drain deadline
BB_CLIENT_WS_MAX_FRAME_PAYLOAD	—	—	the declared inbound WebSocket frame payload is over the cap
BB_CLIENT_WS_MAX_MESSAGE_SIZE	—	—	the reassembled/inflated inbound WebSocket message is over the cap

A time bound records only when its own deadline expired. A TimeoutError that reached the client from inside the transport is not the cap refusing, and is not filed under one.

BB_CLIENT_H2_ENABLE_PUSH and BB_CLIENT_MIN_BODY_RATE_GRACE keep no record because neither is a cap: the first is a conformance switch that refuses nothing on its own, and the second is a grace-period modifier of BB_CLIENT_MIN_BODY_RATE, which owns both the refusal and the record.

BB_WS_QUEUE_DEPTH is intentionally not logged — when read-ahead is enabled at all, the WebSocket event queue applies backpressure (blocking await put()) rather than dropping events, so a hit is normal flow control rather than a rejection. At the default depth of 0 there is no queue to hit. The HTTP/2 per-stream queue (depth controlled by BB_STREAM_QUEUE_DEPTH-style internals) does drop and is logged under the cap name stream_queue_depth.

Record shape

Each record carries the cap name in the message and the structured fields in record.extra:

extra field	Meaning
cap	Cap name (e.g. "ws_max_frame_payload")
requested	Value the peer asked for (frame size, header bytes, …)
limit	Configured cap
peer	Peer (host, port) tuple when available
scope_path	Request path when available
protocol	Refusing subsystem: "http1", "http2", "ws", "h2-ws", "mqtt", "tcp" (connection admission), "transport" (socket drain/backlog), "compression", or a registered extension name. "unknown" means no binding was selected before detection timed out.

Rate limiting

A single misbehaving peer cannot flood the log: each ConnectionActor carries a CapHitCounter (installed via a contextvars-bound context manager so every actor on the same task tree picks it up without plumbing). The first hit per (connection, cap, protocol) logs in full; repeats of that pair are silently counted. Threshold, interval and connection-close summaries retain the refusing subsystem and count each pair separately:

cap hit summary: ws_max_frame_payload suppressed=99 more

Subscribing

import logging

class CapsHandler(logging.Handler):
    def emit(self, record):
        # Forward to your metrics pipeline, page on certain caps, etc.
        print(f"[CAP] {record.cap} requested={record.requested} "
              f"limit={record.limit} peer={record.peer}")

caps = logging.getLogger('blackbull.caps')
caps.addHandler(CapsHandler())
caps.setLevel(logging.WARNING)

In production set the level once at startup and route the records to whatever observability surface you prefer (structured JSON to a log aggregator, Prometheus counters via a custom handler, Sentry breadcrumbs, …). The extra payload is designed to round-trip through json.dumps(record.__dict__) cleanly.

Not yet implemented

• WebSocket access logging — connection-level entry (client IP, path, close code, duration). Today the websocket_* events from Events cover the same data; build your own logger on top if you need persistence.

The access log covers both HTTP/1.1 and HTTP/2 (one entry per completed request / stream).

Next

• Events — @app.on('request_completed') for per-request observability without touching the access log.
• Configuration — environment variables that affect logging (BB_ACCESS_LOG, BB_ASYNC_LOGGING).