mirror of
https://github.com/kennethreitz/responder.git
synced 2026-06-05 06:46:14 +00:00
Add structured logging with per-request context (#604)
## Summary
New `enable_logging=True` parameter on `responder.API()` that provides
structured, request-scoped logging using stdlib `logging` and
`contextvars`.
### What it does
- **`api.log`** — always available on every API instance. Works as a
plain logger by default; gains per-request context enrichment with
`enable_logging=True`
- **Per-request context** — every log message automatically includes
request ID, HTTP method, path, and client IP
- **Access logging** — logs every request with timing: `GET /path → 200
(1.2ms)`
- **Request ID** — generates or forwards `X-Request-ID` headers
(supersedes `request_id=True` when both are set)
- **stdlib logging** — works with any existing handler, formatter, or
log aggregator
### Usage
```python
# api.log always works — no setup required
api = responder.API()
api.log.info("starting up") # plain logger, no context
# With enable_logging=True, log messages get request context automatically
api = responder.API(enable_logging=True)
@api.route("/")
def index(req, resp):
api.log.info("handling request")
# => 2026-03-24 12:00:00 [INFO] responder.app — handling request [GET /] [req:abc123] [client:127.0.0.1]
```
For additional loggers in helper modules:
```python
from responder.ext.logging import get_logger
logger = get_logger("myapp.db")
```
### Architecture
- `responder/ext/logging.py` — self-contained module with:
- `LoggingMiddleware` — pure ASGI middleware that sets contextvars and
logs access
- `RequestContextFilter` — logging filter that injects context into
records
- `RequestContext` — read-only access to current request metadata
- `get_logger()` / `setup_logging()` — convenience functions
- `api.log` — always a valid logger; context-aware when
`enable_logging=True`, plain stdlib logger otherwise
- Wired into `API.__init__` via the `enable_logging` parameter
### Files
- `responder/ext/logging.py` — new module
- `responder/api.py` — added `enable_logging` parameter and `api.log`
- `tests/test_logging.py` — 9 tests
- `docs/source/tour.rst` — new Structured Logging section
- `docs/source/index.rst` — added to feature list
## Test plan
- [x] 9 logging tests pass
- [x] Full suite: 208 passed
🤖 Generated with [Claude Code](https://claude.com/claude-code)
---------
Co-authored-by: Claude Opus 4.6 (1M context) <noreply@anthropic.com>
This commit is contained in:
@@ -0,0 +1,158 @@
|
||||
"""Tests for structured logging with request context."""
|
||||
|
||||
import logging
|
||||
|
||||
import responder
|
||||
from responder.ext.logging import (
|
||||
LoggingMiddleware,
|
||||
RequestContext,
|
||||
RequestContextFilter,
|
||||
get_logger,
|
||||
)
|
||||
|
||||
|
||||
def test_logging_middleware_sets_request_id():
|
||||
"""LoggingMiddleware adds X-Request-ID to responses."""
|
||||
api = responder.API(allowed_hosts=["localhost"], enable_logging=True)
|
||||
|
||||
@api.route("/")
|
||||
def index(req, resp):
|
||||
resp.text = "ok"
|
||||
|
||||
r = api.requests.get("http://localhost/")
|
||||
assert r.status_code == 200
|
||||
assert "x-request-id" in r.headers
|
||||
assert len(r.headers["x-request-id"]) > 0
|
||||
|
||||
|
||||
def test_logging_middleware_forwards_request_id():
|
||||
"""LoggingMiddleware forwards client-provided X-Request-ID."""
|
||||
api = responder.API(allowed_hosts=["localhost"], enable_logging=True)
|
||||
|
||||
@api.route("/")
|
||||
def index(req, resp):
|
||||
resp.text = "ok"
|
||||
|
||||
r = api.requests.get(
|
||||
"http://localhost/", headers={"X-Request-ID": "custom-id-123"}
|
||||
)
|
||||
assert r.headers["x-request-id"] == "custom-id-123"
|
||||
|
||||
|
||||
def test_logging_context_available_in_route():
|
||||
"""Request context is available inside route handlers."""
|
||||
api = responder.API(allowed_hosts=["localhost"], enable_logging=True)
|
||||
captured = {}
|
||||
|
||||
@api.route("/ctx")
|
||||
def index(req, resp):
|
||||
captured["request_id"] = RequestContext.get_request_id()
|
||||
captured["method"] = RequestContext.get_method()
|
||||
captured["path"] = RequestContext.get_path()
|
||||
captured["client_ip"] = RequestContext.get_client_ip()
|
||||
resp.text = "ok"
|
||||
|
||||
api.requests.get("http://localhost/ctx")
|
||||
assert captured["method"] == "GET"
|
||||
assert captured["path"] == "/ctx"
|
||||
assert captured["request_id"] != "-"
|
||||
assert captured["client_ip"] != "-"
|
||||
|
||||
|
||||
def test_logging_filter_injects_attributes():
|
||||
"""RequestContextFilter adds context fields to log records."""
|
||||
logger = get_logger("test.filter")
|
||||
records = []
|
||||
|
||||
class CaptureHandler(logging.Handler):
|
||||
def emit(self, record):
|
||||
records.append(record)
|
||||
|
||||
handler = CaptureHandler()
|
||||
logger.addHandler(handler)
|
||||
logger.setLevel(logging.DEBUG)
|
||||
|
||||
api = responder.API(allowed_hosts=["localhost"], enable_logging=True)
|
||||
|
||||
@api.route("/log")
|
||||
def index(req, resp):
|
||||
logger.info("test message")
|
||||
resp.text = "ok"
|
||||
|
||||
api.requests.get("http://localhost/log")
|
||||
|
||||
logger.removeHandler(handler)
|
||||
|
||||
assert len(records) > 0
|
||||
record = records[0]
|
||||
assert hasattr(record, "request_id")
|
||||
assert hasattr(record, "request_method")
|
||||
assert hasattr(record, "request_path")
|
||||
assert hasattr(record, "client_ip")
|
||||
assert record.request_method == "GET"
|
||||
assert record.request_path == "/log"
|
||||
|
||||
|
||||
def test_get_logger_avoids_duplicate_filters():
|
||||
"""get_logger doesn't add duplicate filters."""
|
||||
logger = get_logger("test.dedup")
|
||||
count_before = sum(1 for f in logger.filters if isinstance(f, RequestContextFilter))
|
||||
get_logger("test.dedup")
|
||||
count_after = sum(1 for f in logger.filters if isinstance(f, RequestContextFilter))
|
||||
assert count_before == count_after == 1
|
||||
|
||||
|
||||
def test_enable_logging_supersedes_request_id():
|
||||
"""enable_logging handles request IDs itself (no duplicate headers)."""
|
||||
api = responder.API(
|
||||
allowed_hosts=["localhost"], request_id=True, enable_logging=True
|
||||
)
|
||||
|
||||
@api.route("/")
|
||||
def index(req, resp):
|
||||
resp.text = "ok"
|
||||
|
||||
r = api.requests.get("http://localhost/")
|
||||
# Should have exactly one X-Request-ID header.
|
||||
assert "x-request-id" in r.headers
|
||||
|
||||
|
||||
def test_api_logger_attribute():
|
||||
"""api.log is available when enable_logging=True."""
|
||||
api = responder.API(allowed_hosts=["localhost"], enable_logging=True)
|
||||
assert api.log is not None
|
||||
assert api.log.name == "responder.app"
|
||||
|
||||
|
||||
def test_api_log_always_available():
|
||||
"""api.log works even without enable_logging — just no request context."""
|
||||
api = responder.API(allowed_hosts=["localhost"])
|
||||
assert api.log is not None
|
||||
assert api.log.name == "responder.app"
|
||||
api.log.info("works without enable_logging")
|
||||
|
||||
|
||||
def test_api_logger_works_in_routes():
|
||||
"""api.log can be used inside route handlers with context."""
|
||||
api = responder.API(allowed_hosts=["localhost"], enable_logging=True)
|
||||
records = []
|
||||
|
||||
class CaptureHandler(logging.Handler):
|
||||
def emit(self, record):
|
||||
records.append(record)
|
||||
|
||||
handler = CaptureHandler()
|
||||
api.log.addHandler(handler)
|
||||
|
||||
@api.route("/")
|
||||
def index(req, resp):
|
||||
api.log.info("hello from route")
|
||||
resp.text = "ok"
|
||||
|
||||
api.requests.get("http://localhost/")
|
||||
api.log.removeHandler(handler)
|
||||
|
||||
assert any(r.msg == "hello from route" for r in records)
|
||||
record = next(r for r in records if r.msg == "hello from route")
|
||||
assert record.request_method == "GET"
|
||||
assert record.request_path == "/"
|
||||
Reference in New Issue
Block a user