Access log vars

README.md

@@ -420,6 +420,11 @@ The following atoms are available for use:
 | method | Request HTTP method |
 | scheme | Request scheme |
 | protocol | HTTP protocol version |
+| user\_agent | Request User-Agent header |
+
+Arbitrary request headers can be accessed using `%({Header-Name}i)s` (case-insensitive), e.g. `%({X-Request-Id}i)s`.
+
+Arbitrary response headers can be accessed using `%({Header-Name}o)s` (case-insensitive), e.g. `%({X-Trace-Id}o)s`.
 
 ### Workers and threads
 

granian/asgi.py

@@ -120,16 +120,34 @@ async def _http_logger(scope, proto):
             access_log(rt, mt, scope, proto.sent_response_code)
         return rv
 
+    async def _http_logger_with_resp_headers(scope, proto):
+        rt, mt = time.time(), time.perf_counter()
+        resp_headers_raw = []
+        original_send = proto.send
+
+        async def capturing_send(message):
+            if message.get('type') == 'http.response.start':
+                resp_headers_raw.extend(message.get('headers', ()))
+            return await original_send(message)
+
+        try:
+            scope.update(root_path=root_url_path, state=state.copy())
+            rv = await callback(scope, proto.receive, capturing_send)
+        finally:
+            access_log(rt, mt, scope, proto.sent_response_code, resp_headers_raw)
+        return rv
+
     def _ws_logger(scope, proto):
         access_log(time.time(), time.perf_counter(), scope, 101)
         return _runner(scope, proto)
 
     def _logger(scope, proto):
         if scope['type'] == 'http':
-            return _http_logger(scope, proto)
+            return _http_log(scope, proto)
         return _ws_logger(scope, proto)
 
-    access_log = _build_access_logger(access_log_fmt)
+    access_log, _needs_resp_headers = _build_access_logger(access_log_fmt)
+    _http_log = _http_logger_with_resp_headers if _needs_resp_headers else _http_logger
     wrapper = _logger if access_log_fmt else _runner
     wraps(callback)(wrapper)
 
@@ -138,20 +156,32 @@ def _logger(scope, proto):
 
 def _build_access_logger(fmt):
     logger = log_request_builder(fmt)
-
-    def access_log(rt, mt, scope, resp_code):
-        logger(
-            rt,
-            mt,
-            {
-                'addr_remote': scope['client'][0],
-                'protocol': 'HTTP/' + scope['http_version'],
-                'path': scope['path'],
-                'qs': scope['query_string'],
-                'method': scope.get('method', '-'),
-                'scheme': scope['scheme'],
-            },
-            resp_code,
-        )
-
-    return access_log
+    _needs_resp_headers = logger.needs_resp_headers
+
+    def access_log(rt, mt, scope, resp_code, resp_headers_raw=()):
+        user_agent = '-'
+        headers_dict = {}
+        for hname_b, hval_b in scope.get('headers', ()):
+            hname = hname_b.decode('latin-1').lower()
+            hval = hval_b.decode('latin-1')
+            headers_dict[hname] = hval
+            if hname == 'user-agent':
+                user_agent = hval
+        req = {
+            'addr_remote': scope['client'][0],
+            'protocol': 'HTTP/' + scope['http_version'],
+            'path': scope['path'],
+            'qs': scope['query_string'],
+            'method': scope.get('method', '-'),
+            'scheme': scope['scheme'],
+            'user_agent': user_agent,
+            'get_header': headers_dict.get,
+        }
+        if _needs_resp_headers:
+            req['get_response_header'] = {
+                hname_b.decode('latin-1').lower(): hval_b.decode('latin-1')
+                for hname_b, hval_b in resp_headers_raw
+            }.get
+        logger(rt, mt, req, resp_code)
+
+    return access_log, _needs_resp_headers

granian/log.py

@@ -2,6 +2,7 @@
 import datetime
 import logging
 import logging.config
+import re
 import time
 from enum import Enum
 from typing import Any
@@ -72,27 +73,76 @@ def configure_logging(level: LogLevels, config: dict[str, Any] | None = None, en
         logger.setLevel(logging.CRITICAL + 1)
 
 
+_REQUEST_HEADER_RE = re.compile(r'%\(\{([^}]+)\}i\)s')
+_RESPONSE_HEADER_RE = re.compile(r'%\(\{([^}]+)\}o\)s')
+
+
 def log_request_builder(fmt):
+    required_req_headers = []
+    required_resp_headers = []
+
+    def _replace_req(m):
+        name = m.group(1).strip().lower()
+        required_req_headers.append(name)
+        return f'%(header:{name})s'
+
+    def _replace_resp(m):
+        name = m.group(1).strip().lower()
+        required_resp_headers.append(name)
+        return f'%(resp_header:{name})s'
+
+    transformed_fmt = _REQUEST_HEADER_RE.sub(_replace_req, fmt)
+    transformed_fmt = _RESPONSE_HEADER_RE.sub(_replace_resp, transformed_fmt)
+
+    # Validate the format string eagerly so misconfiguration is caught at startup,
+    # not silently swallowed on the first real request.
+    _dummy = {
+        'addr': '127.0.0.1',
+        'time': '2000-01-01 00:00:00 +0000',
+        'dt_ms': 0.0,
+        'status': 200,
+        'path': '/',
+        'query_string': '',
+        'method': 'GET',
+        'scheme': 'http',
+        'protocol': 'HTTP/1.1',
+        'user_agent': '-',
+        **{f'header:{h}': '-' for h in required_req_headers},
+        **{f'resp_header:{h}': '-' for h in required_resp_headers},
+    }
+    try:
+        transformed_fmt % _dummy
+    except (KeyError, ValueError) as exc:
+        raise ValueError(f'Invalid access log format: {exc}') from exc
+
     now = datetime.datetime.now()
     local_now = now.astimezone()
     local_tz = local_now.tzinfo
 
     def log_request(rtime, mtime, req, res_code):
         dt = time.perf_counter() - mtime
         rdt = datetime.datetime.fromtimestamp(rtime, tz=local_tz)
-        access_logger.info(
-            fmt,
-            {
-                'addr': req['addr_remote'],
-                'time': rdt.strftime('%Y-%m-%d %H:%M:%S %z'),
-                'dt_ms': dt * 1000,
-                'status': res_code,
-                'path': req['path'],
-                'query_string': req['qs'],
-                'method': req['method'],
-                'scheme': req['scheme'],
-                'protocol': req['protocol'],
-            },
-        )
-
+        log_dict = {
+            'addr': req['addr_remote'],
+            'time': rdt.strftime('%Y-%m-%d %H:%M:%S %z'),
+            'dt_ms': dt * 1000,
+            'status': res_code,
+            'path': req['path'],
+            'query_string': req['qs'],
+            'method': req['method'],
+            'scheme': req['scheme'],
+            'protocol': req['protocol'],
+            'user_agent': req['user_agent'],
+        }
+        if required_req_headers:
+            get_header = req.get('get_header') or (lambda _: None)
+            for hname in required_req_headers:
+                log_dict[f'header:{hname}'] = get_header(hname) or '-'
+        if required_resp_headers:
+            get_resp_header = req.get('get_response_header') or (lambda _: None)
+            for hname in required_resp_headers:
+                log_dict[f'resp_header:{hname}'] = get_resp_header(hname) or '-'
+        access_logger.info(transformed_fmt, log_dict)
+
+    log_request.needs_resp_headers = bool(required_resp_headers)
     return log_request

granian/rsgi.py

@@ -40,11 +40,12 @@ class WebsocketMessage:
 
 
 class _LoggingProto:
-    __slots__ = ['inner', 'status']
+    __slots__ = ['inner', 'status', 'resp_headers']
 
     def __init__(self, inner):
         self.inner = inner
         self.status = 500
+        self.resp_headers = ()
 
     def __call__(self):
         return self.inner()
@@ -57,26 +58,32 @@ def client_disconnect(self):
 
     def response_empty(self, status, headers):
         self.status = status
+        self.resp_headers = headers
         return self.inner.response_empty(status, headers)
 
     def response_str(self, status, headers, body):
         self.status = status
+        self.resp_headers = headers
         return self.inner.response_str(status, headers, body)
 
     def response_bytes(self, status, headers, body):
         self.status = status
+        self.resp_headers = headers
         return self.inner.response_bytes(status, headers, body)
 
     def response_file(self, status, headers, file):
         self.status = status
+        self.resp_headers = headers
         return self.inner.response_file(status, headers, file)
 
     def response_file_range(self, status, headers, file, start, end):
         self.status = status
+        self.resp_headers = headers
         return self.inner.response_file_range(status, headers, file, start, end)
 
     def response_stream(self, status, headers):
         self.status = status
+        self.resp_headers = headers
         return self.inner.response_stream(status, headers)
 
 
@@ -98,16 +105,25 @@ async def _http_logger(scope, proto):
             access_log(rt, mt, scope, proto.status)
         return rv
 
+    async def _http_logger_with_resp_headers(scope, proto):
+        rt, mt = time.time(), time.perf_counter()
+        try:
+            rv = await callback(scope, proto)
+        finally:
+            access_log(rt, mt, scope, proto.status, proto.resp_headers)
+        return rv
+
     def _ws_logger(scope, proto):
         access_log(time.time(), time.perf_counter(), scope, 101)
         return callback(scope, proto)
 
     def _logger(scope, proto):
         if scope.proto == 'http':
-            return _http_logger(scope, _LoggingProto(proto))
+            return _http_log(scope, _LoggingProto(proto))
         return _ws_logger(scope, proto)
 
-    access_log = _build_access_logger(access_log_fmt)
+    access_log, _needs_resp_headers = _build_access_logger(access_log_fmt)
+    _http_log = _http_logger_with_resp_headers if _needs_resp_headers else _http_logger
     wrapper = callback
     if access_log_fmt:
         wrapper = _logger
@@ -117,20 +133,22 @@ def _logger(scope, proto):
 
 def _build_access_logger(fmt):
     logger = log_request_builder(fmt)
-
-    def access_log(rt, mt, scope, resp_code):
-        logger(
-            rt,
-            mt,
-            {
-                'addr_remote': scope.client.rsplit(':', 1)[0],
-                'protocol': 'HTTP/' + scope.http_version,
-                'path': scope.path,
-                'qs': scope.query_string,
-                'method': scope.method,
-                'scheme': scope.scheme,
-            },
-            resp_code,
-        )
-
-    return access_log
+    _needs_resp_headers = logger.needs_resp_headers
+
+    def access_log(rt, mt, scope, resp_code, resp_headers=()):
+        req = {
+            'addr_remote': scope.client.rsplit(':', 1)[0],
+            'protocol': 'HTTP/' + scope.http_version,
+            'path': scope.path,
+            'qs': scope.query_string,
+            'method': scope.method,
+            'scheme': scope.scheme,
+            'user_agent': scope.headers.get('user-agent') or '-',
+            'get_header': scope.headers.get,
+        }
+        if _needs_resp_headers:
+            # RSGI response headers are (str, str) tuples
+            req['get_response_header'] = {hname.lower(): hval for hname, hval in resp_headers}.get
+        logger(rt, mt, req, resp_code)
+
+    return access_log, _needs_resp_headers