diff --git a/docs/source/index.rst b/docs/source/index.rst index f48987b..7bf221b 100644 --- a/docs/source/index.rst +++ b/docs/source/index.rst @@ -73,6 +73,7 @@ One ``pip install``, batteries included: - Sync and async views — ``async`` is always optional. - Class-based views with ``on_get``, ``on_post``, ``on_request``. - Built-in rate limiting with ``X-RateLimit`` headers. +- Structured logging with per-request context. - Content negotiation: JSON, YAML, and MessagePack. - A pleasant API with a single import statement. - OpenAPI schema generation with Swagger UI. diff --git a/docs/source/tour.rst b/docs/source/tour.rst index 6063fa8..aa81c2c 100644 --- a/docs/source/tour.rst +++ b/docs/source/tour.rst @@ -596,6 +596,60 @@ can pace themselves. The rate limiter is per-client, keyed by IP address. +Structured Logging +------------------ + +Production applications need structured, searchable logs. Responder +includes built-in logging that automatically attaches request context +— request ID, HTTP method, path, and client IP — to every log message +emitted during request handling:: + + api = responder.API(enable_logging=True) + +This gives you: + +- **Access logging** with timing for every request:: + + 2026-03-24 12:00:00 [INFO] responder.access — GET /users → 200 (1.2ms) + +- **A logger on the API instance** — use ``api.log`` anywhere in + your routes. Request context (ID, method, path, client IP) is + attached automatically:: + + @api.route("/users/{user_id:int}") + def get_user(req, resp, *, user_id): + api.log.info("fetching user %d", user_id) + # => [INFO] responder.app -- fetching user 42 [GET /users/42] [req:a1b2c3] [client:10.0.0.1] + resp.media = {"id": user_id} + +- **Request IDs** generated automatically (or forwarded from the + ``X-Request-ID`` header) and included in responses. + +The logging uses Python's standard ``logging`` module, so it works with +any handler — files, syslog, JSON formatters, Datadog, Sentry, whatever +you already use. + +For additional loggers (e.g. in helper modules), use ``get_logger``:: + + from responder.ext.logging import get_logger + logger = get_logger("myapp.db") + +You can also access the current request context directly:: + + from responder.ext.logging import RequestContext + + @api.route("/debug") + def debug(req, resp): + resp.media = { + "request_id": RequestContext.get_request_id(), + "client_ip": RequestContext.get_client_ip(), + } + +When ``enable_logging=True`` is set, it supersedes ``request_id=True`` +— the logging middleware handles request IDs itself, so you don't get +duplicate headers. + + Pydantic Validation ------------------- diff --git a/responder/api.py b/responder/api.py index 6f8f473..4ce8ad3 100644 --- a/responder/api.py +++ b/responder/api.py @@ -61,6 +61,7 @@ class API: openapi_theme=DEFAULT_OPENAPI_THEME, lifespan=None, request_id=False, + enable_logging=False, ): """Create a new Responder API instance. @@ -86,6 +87,7 @@ class API: :param openapi_theme: Documentation UI theme: ``"swagger_ui"``, ``"redoc"``, ``"rapidoc"``, or ``"elements"``. :param lifespan: An async context manager for startup/shutdown logic. :param request_id: If ``True``, add ``X-Request-ID`` headers to all responses. + :param enable_logging: If ``True``, enable structured logging with per-request context (request ID, method, path, client IP). """ # noqa: E501 self.background = BackgroundQueue() @@ -158,7 +160,7 @@ class API: self.templates = Templates(directory=templates_dir) - if request_id: + if request_id and not enable_logging: import uuid as _uuid def _add_request_id(req, resp): @@ -167,6 +169,20 @@ class API: self.router.after_request(_add_request_id) + if enable_logging: + import logging as _logging + + from .ext.logging import LoggingMiddleware, get_logger, setup_logging + + log_level = _logging.DEBUG if debug else _logging.INFO + setup_logging(level=log_level) + self.add_middleware(LoggingMiddleware) + self.log = get_logger("responder.app") + else: + import logging as _logging + + self.log = _logging.getLogger("responder.app") + @property def requests(self): """A test client connected to the ASGI app. Lazily initialized.""" diff --git a/responder/ext/logging.py b/responder/ext/logging.py new file mode 100644 index 0000000..5ba2dd5 --- /dev/null +++ b/responder/ext/logging.py @@ -0,0 +1,181 @@ +"""Structured logging with per-request context. + +Provides a logging setup that automatically includes request metadata +(request ID, method, path, client IP) in every log message emitted +during request handling. + +Usage:: + + api = responder.API(enable_logging=True) + + # In any route or middleware: + from responder.ext.logging import get_logger + logger = get_logger(__name__) + + @api.route("/") + def index(req, resp): + logger.info("handling request") + # => 2026-03-24 12:00:00 [INFO] app — handling request [GET /] [req:abc123] [client:127.0.0.1] +""" + +from __future__ import annotations + +import logging +import time +import uuid +from contextvars import ContextVar + +__all__ = ["get_logger", "RequestContext", "RequestContextFilter", "LoggingMiddleware"] + +# Context variables for per-request metadata. +_request_id: ContextVar[str] = ContextVar("request_id", default="-") +_request_method: ContextVar[str] = ContextVar("request_method", default="-") +_request_path: ContextVar[str] = ContextVar("request_path", default="-") +_client_ip: ContextVar[str] = ContextVar("client_ip", default="-") + + +class RequestContext: + """Read-only access to the current request's logging context.""" + + @staticmethod + def get_request_id() -> str: + return _request_id.get() + + @staticmethod + def get_method() -> str: + return _request_method.get() + + @staticmethod + def get_path() -> str: + return _request_path.get() + + @staticmethod + def get_client_ip() -> str: + return _client_ip.get() + + +class RequestContextFilter(logging.Filter): + """A logging filter that injects request context into log records. + + Adds ``request_id``, ``request_method``, ``request_path``, and + ``client_ip`` attributes to every log record, so they can be used + in format strings. + """ + + def filter(self, record: logging.LogRecord) -> bool: + record.request_id = _request_id.get() # type: ignore[attr-defined] + record.request_method = _request_method.get() # type: ignore[attr-defined] + record.request_path = _request_path.get() # type: ignore[attr-defined] + record.client_ip = _client_ip.get() # type: ignore[attr-defined] + return True + + +# Default format that includes request context. +DEFAULT_LOG_FORMAT = ( + "%(asctime)s [%(levelname)s] %(name)s -- %(message)s " + "[%(request_method)s %(request_path)s] " + "[req:%(request_id)s] [client:%(client_ip)s]" +) + + +def get_logger(name: str | None = None) -> logging.Logger: + """Get a logger with the request context filter attached. + + :param name: Logger name (typically ``__name__``). + :returns: A :class:`logging.Logger` with request context available. + """ + logger = logging.getLogger(name) + # Avoid adding duplicate filters. + if not any(isinstance(f, RequestContextFilter) for f in logger.filters): + logger.addFilter(RequestContextFilter()) + return logger + + +def setup_logging(level: int = logging.INFO) -> None: + """Configure the root logger with request-context-aware formatting. + + :param level: The logging level (default ``INFO``). + """ + root = logging.getLogger() + root.setLevel(level) + + # Only add our handler if the root logger has no handlers yet, + # or if none of them use our filter. + has_context_handler = any( + any(isinstance(f, RequestContextFilter) for f in h.filters) + for h in root.handlers + ) + if not has_context_handler: + handler = logging.StreamHandler() + handler.setLevel(level) + handler.addFilter(RequestContextFilter()) + handler.setFormatter(logging.Formatter(DEFAULT_LOG_FORMAT)) + root.addHandler(handler) + + +class LoggingMiddleware: + """ASGI middleware that sets per-request context variables. + + For each HTTP request, this middleware: + + 1. Extracts or generates a request ID + 2. Sets context variables for method, path, and client IP + 3. Logs the request and response with timing information + """ + + def __init__(self, app, logger_name: str = "responder.access"): + self.app = app + self.logger = get_logger(logger_name) + + async def __call__(self, scope, receive, send): + if scope["type"] not in ("http", "websocket"): + await self.app(scope, receive, send) + return + + # Extract request metadata. + headers = dict(scope.get("headers", [])) + request_id = ( + headers.get(b"x-request-id", b"").decode() or uuid.uuid4().hex[:8] + ) + method = scope.get("method", "WS") + path = scope.get("path", "/") + client = scope.get("client") + client_ip = client[0] if client else "-" + + # Set context variables for the duration of this request. + tok_id = _request_id.set(request_id) + tok_method = _request_method.set(method) + tok_path = _request_path.set(path) + tok_ip = _client_ip.set(client_ip) + + # Track response status. + status_code = None + + async def send_wrapper(message): + nonlocal status_code + if message["type"] == "http.response.start": + status_code = message.get("status") + # Inject request ID into response headers. + headers_list = list(message.get("headers", [])) + headers_list.append((b"x-request-id", request_id.encode())) + message = {**message, "headers": headers_list} + await send(message) + + start = time.perf_counter() + try: + await self.app(scope, receive, send_wrapper) + finally: + duration_ms = (time.perf_counter() - start) * 1000 + if scope["type"] == "http": + self.logger.info( + "%s %s → %s (%.1fms)", + method, + path, + status_code or "?", + duration_ms, + ) + # Reset context variables. + _request_id.reset(tok_id) + _request_method.reset(tok_method) + _request_path.reset(tok_path) + _client_ip.reset(tok_ip) diff --git a/tests/test_logging.py b/tests/test_logging.py new file mode 100644 index 0000000..9a90239 --- /dev/null +++ b/tests/test_logging.py @@ -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 == "/"