Implement access log format

docs/deployment.md

@@ -70,6 +70,8 @@ Options:
   --log-level [critical|error|warning|info|debug|trace]
                                   Log level. [default: info]
   --access-log / --no-access-log  Enable/Disable access log.
+  --access-log-format TEXT        Log format for access logger, check
+                                  documentation for details.
   --use-colors / --no-use-colors  Enable/Disable colorized logging.
   --proxy-headers / --no-proxy-headers
                                   Enable/Disable X-Forwarded-Proto,

docs/index.md

@@ -143,6 +143,8 @@ Options:
   --log-level [critical|error|warning|info|debug|trace]
                                   Log level. [default: info]
   --access-log / --no-access-log  Enable/Disable access log.
+  --access-log-format TEXT        Log format for access logger, check
+                                  documentation for details.
   --use-colors / --no-use-colors  Enable/Disable colorized logging.
   --proxy-headers / --no-proxy-headers
                                   Enable/Disable X-Forwarded-Proto,

requirements.txt

@@ -23,6 +23,7 @@ coverage
 httpx>=0.18.2
 pytest-asyncio==0.14.*
 async_generator; python_version < '3.7'
+gunicorn
 
 
 # Documentation

tests/middleware/test_logging.py

@@ -1,5 +1,6 @@
 import contextlib
 import logging
+import re
 
 import httpx
 import pytest
@@ -9,6 +10,11 @@
 from uvicorn import Config
 
 
+def escape_ansi(line: str):
+    ansi_escape = re.compile(r"(?:\x1B[@-_]|[\x80-\x9F])[0-?]*[ -/]*[@-~]")
+    return ansi_escape.sub("", line)
+
+
 @contextlib.contextmanager
 def caplog_for_logger(caplog, logger_name):
     logger = logging.getLogger(logger_name)
@@ -110,7 +116,7 @@ async def test_access_logging(use_colors, caplog):
             for record in caplog.records
             if record.name == "uvicorn.access"
         ]
-        assert '"GET / HTTP/1.1" 204' in messages.pop()
+        assert '"GET / HTTP/1.1" 204' in escape_ansi(messages.pop())
 
 
 @pytest.mark.asyncio
@@ -130,7 +136,7 @@ async def test_default_logging(use_colors, caplog):
         assert "ASGI 'lifespan' protocol appears unsupported" in messages.pop(0)
         assert "Application startup complete" in messages.pop(0)
         assert "Uvicorn running on http://127.0.0.1:8000" in messages.pop(0)
-        assert '"GET / HTTP/1.1" 204' in messages.pop(0)
+        assert '"GET / HTTP/1.1" 204' in escape_ansi(messages.pop(0))
         assert "Shutting down" in messages.pop(0)
 
 

uvicorn/config.py

@@ -202,6 +202,7 @@ def __init__(
         log_config: Optional[Union[dict, str]] = LOGGING_CONFIG,
         log_level: Optional[Union[str, int]] = None,
         access_log: bool = True,
+        access_log_format: Optional[str] = None,
         use_colors: Optional[bool] = None,
         interface: InterfaceType = "auto",
         debug: bool = False,
@@ -274,6 +275,11 @@ def __init__(
         self.encoded_headers: List[Tuple[bytes, bytes]] = []
         self.factory = factory
 
+        if access_log_format is None:
+            self.access_log_format = '%(h)s - "%(request_line)s" %(status_code)s'
+        else:
+            self.access_log_format = access_log_format
+
         self.loaded = False
         self.configure_logging()
 
@@ -375,6 +381,10 @@ def configure_logging(self) -> None:
                     self.log_config["formatters"]["access"][
                         "use_colors"
                     ] = self.use_colors
+                if self.access_log_format:
+                    self.log_config["formatters"]["access"][
+                        "fmt"
+                    ] = "%(levelprefix)s %(message)s"
                 logging.config.dictConfig(self.log_config)
             elif self.log_config.endswith(".json"):
                 with open(self.log_config) as file:

uvicorn/logging.py

@@ -1,10 +1,15 @@
 import http
 import logging
+import os
 import sys
+import time
 from copy import copy
 from typing import Optional
 
 import click
+from asgiref.typing import HTTPResponseStartEvent, HTTPScope
+
+from uvicorn.protocols.utils import get_client_addr, get_path_with_query_string
 
 TRACE_LOG_LEVEL = 5
 
@@ -96,22 +101,76 @@ def default(code: int) -> str:
 
     def formatMessage(self, record: logging.LogRecord) -> str:
         recordcopy = copy(record)
-        (
-            client_addr,
-            method,
-            full_path,
-            http_version,
-            status_code,
-        ) = recordcopy.args
+        request_line = recordcopy.args["request_line"]  # type: ignore[call-overload]
+        status_code = recordcopy.args["s"]  # type: ignore[call-overload]
+
         status_code = self.get_status_code(int(status_code))
-        request_line = "%s %s HTTP/%s" % (method, full_path, http_version)
         if self.use_colors:
             request_line = click.style(request_line, bold=True)
-        recordcopy.__dict__.update(
+        recordcopy.args["request_line"] = request_line  # type: ignore[index]
+        recordcopy.args["status_code"] = status_code  # type: ignore[index]
+        return super().formatMessage(recordcopy)
+
+
+class AccessLogFields(dict):
+    def __init__(
+        self,
+        scope: HTTPScope,
+        response: HTTPResponseStartEvent,
+        request_time: float,
+    ) -> None:
+        for name, value in scope["headers"]:
+            self[f"{{{name.decode('latin1').lower()}}}i"] = value.decode("latin1")
+        for name, value in response.get("headers", []):
+            self[f"{{{name.decode('latin1').lower()}}}o"] = value.decode("latin1")
+        for name, value in os.environ.items():  # type: ignore[assignment]
+            self[f"{{{name.lower()!r}}}e"] = value
+        protocol = f"HTTP/{scope['http_version']}"
+        path = scope["root_path"] + scope["path"]
+        full_path = get_path_with_query_string(scope)
+        request_line = f"{scope['method']} {path} {protocol}"
+        full_request_line = f"{scope['method']} {full_path} {protocol}"
+        client_addr = get_client_addr(scope) or "-"
+
+        try:
+            status_phrase = http.HTTPStatus(response["status"]).phrase
+        except ValueError:
+            status_phrase = "-"
+
+        self.update(
             {
+                "h": client_addr,
                 "client_addr": client_addr,
-                "request_line": request_line,
-                "status_code": status_code,
+                "l": "-",
+                "u": "-",  # Not available on ASGI.
+                "t": time.strftime("[%d/%b/%Y:%H:%M:%S %z]"),
+                "r": request_line,
+                "request_line": full_request_line,
+                "R": full_request_line,
+                "m": scope["method"],
+                "U": scope["path"],
+                "q": scope["query_string"].decode(),
+                "H": protocol,
+                "s": response["status"],
+                "st": status_phrase,
+                "status_code": f"{response['status']} {status_phrase}",
+                "B": self["{Content-Length}o"],
+                "b": self.get("{Content-Length}o", "-"),
+                "f": self["{Referer}i"],
+                "a": self["{User-Agent}i"],
+                "T": int(request_time),
+                "M": int(request_time * 1_000),
+                "D": int(request_time * 1_000_000),
+                "L": f"{request_time:.6f}",
+                "p": f"<{os.getpid()}>",
             }
         )
-        return super().formatMessage(recordcopy)
+
+    def __getitem__(self, key: str) -> str:
+        try:
+            if key.startswith("{"):
+                return super().__getitem__(key.lower())
+            else:
+                return super().__getitem__(key)
+        except KeyError:
+            return "-"

uvicorn/main.py

@@ -192,6 +192,12 @@ def print_version(ctx: click.Context, param: click.Parameter, value: bool) -> No
     default=True,
     help="Enable/Disable access log.",
 )
+@click.option(
+    "--access-log-format",
+    type=str,
+    default=None,
+    help="Log format for access logger, check documentation for details.",
+)
 @click.option(
     "--use-colors/--no-use-colors",
     is_flag=True,
@@ -355,6 +361,7 @@ def main(
     log_config: str,
     log_level: str,
     access_log: bool,
+    access_log_format: str,
     proxy_headers: bool,
     server_header: bool,
     date_header: bool,
@@ -394,6 +401,7 @@ def main(
         "log_config": LOGGING_CONFIG if log_config is None else log_config,
         "log_level": log_level,
         "access_log": access_log,
+        "access_log_format": access_log_format,
         "interface": interface,
         "debug": debug,
         "reload": reload,

uvicorn/protocols/http/h11_impl.py

@@ -1,25 +1,22 @@
 import asyncio
 import http
 import logging
+import traceback
+from time import time
 from typing import Callable
 from urllib.parse import unquote
 
 import h11
+from asgiref.typing import HTTPResponseStartEvent
 
-from uvicorn.logging import TRACE_LOG_LEVEL
+from uvicorn.logging import TRACE_LOG_LEVEL, AccessLogFields
 from uvicorn.protocols.http.flow_control import (
     CLOSE_HEADER,
     HIGH_WATER_LIMIT,
     FlowControl,
     service_unavailable,
 )
-from uvicorn.protocols.utils import (
-    get_client_addr,
-    get_local_addr,
-    get_path_with_query_string,
-    get_remote_addr,
-    is_ssl,
-)
+from uvicorn.protocols.utils import get_local_addr, get_remote_addr, is_ssl
 
 
 def _get_status_phrase(status_code):
@@ -199,6 +196,7 @@ def handle_events(self):
                     logger=self.logger,
                     access_logger=self.access_logger,
                     access_log=self.access_log,
+                    access_log_format=self.config.access_log_format,
                     default_headers=self.default_headers,
                     message_event=asyncio.Event(),
                     on_response=self.on_response_complete,
@@ -339,6 +337,7 @@ def __init__(
         logger,
         access_logger,
         access_log,
+        access_log_format,
         default_headers,
         message_event,
         on_response,
@@ -350,6 +349,7 @@ def __init__(
         self.logger = logger
         self.access_logger = access_logger
         self.access_log = access_log
+        self.access_log_format = access_log_format
         self.default_headers = default_headers
         self.message_event = message_event
         self.on_response = on_response
@@ -366,6 +366,8 @@ def __init__(
         # Response state
         self.response_started = False
         self.response_complete = False
+        self.start_time = time()
+        self.response: HTTPResponseStartEvent
 
     # ASGI exception wrapper
     async def run_asgi(self, app):
@@ -425,6 +427,7 @@ async def send(self, message):
                 msg = "Expected ASGI message 'http.response.start', but got '%s'."
                 raise RuntimeError(msg % message_type)
 
+            self.response = message
             self.response_started = True
             self.waiting_for_100_continue = False
 
@@ -434,16 +437,6 @@ async def send(self, message):
             if CLOSE_HEADER in self.scope["headers"] and CLOSE_HEADER not in headers:
                 headers = headers + [CLOSE_HEADER]
 
-            if self.access_log:
-                self.access_logger.info(
-                    '%s - "%s %s HTTP/%s" %d',
-                    get_client_addr(self.scope),
-                    self.scope["method"],
-                    get_path_with_query_string(self.scope),
-                    self.scope["http_version"],
-                    status_code,
-                )
-
             # Write response status line and headers
             reason = STATUS_PHRASES[status_code]
             event = h11.Response(
@@ -477,6 +470,17 @@ async def send(self, message):
                 output = self.conn.send(event)
                 self.transport.write(output)
 
+                if self.access_log:
+                    try:
+                        self.access_logger.info(
+                            self.access_log_format,
+                            AccessLogFields(
+                                self.scope, self.response, time() - self.start_time
+                            ),
+                        )
+                    except:  # noqa
+                        self.logger.error(traceback.format_exc())
+
         else:
             # Response already sent
             msg = "Unexpected ASGI message '%s' sent, after response already completed."