Implement gunicorn access log format

docs/deployment.md

@@ -74,6 +74,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,

docs/settings.md

@@ -46,7 +46,27 @@ By default Uvicorn uses simple changes detection strategy that compares python f
 * `--log-level <str>` - Set the log level. **Options:** *'critical', 'error', 'warning', 'info', 'debug', 'trace'.* **Default:** *'info'*.
 * `--no-access-log` - Disable access log only, without changing log level.
 * `--use-colors / --no-use-colors` - Enable / disable colorized formatting of the log records, in case this is not set it will be auto-detected. This option is ignored if the `--log-config` CLI option is used.
-
+* `--access-log-format` - Customized message for access log. Will override log formatter for `uvicorn.access` logger. Format string that supports the following placeholders:
+    * `%(h)s` - remote IP address
+    * `%(l)s` - prints `-`
+    * `%(u)s` - user name, currently not supported, prints `-`
+    * `%(t)s` - request timestamp (in Apache Common Log Format `[10/Oct/2000:13:55:36 -0700]`)
+    * `%(r)s` - status line (method, path & http version, e.g.)
+    * `%(m)s` - request method
+    * `%(U)s` - request path
+    * `%(q)s` - request query string
+    * `%(H)s` - request protocol
+    * `%(s)s` - response status code
+    * `%(B)s` - response body length (if body was empty, prints `0`)
+    * `%(b)s` - response body length (if body was empty, prints `-`)
+    * `%(f)s` - request referer
+    * `%(a)s` - request user agent
+    * `%(T)s` - request+response time (in seconds, integer number)
+    * `%(D)s` - request+response time (in milliseconds, integer number)
+    * `%(L)s` - request+response time (in seconds, decimal number)
+    * `%(p)s` - process id (pid) of request handler
+    * `%({...}i)s` - value of arbitrary request header, e.g. `%({Accept-Encoding}i)s`
+    * `%({...}o)s` - value of arbitrary response header, e.g. `%({Content-Encoding}o)s`
 
 ## Implementation
 

requirements.txt

@@ -23,6 +23,8 @@ coverage==5.5
 coverage-conditional-plugin==0.4.0
 httpx==1.0.0b0
 pytest-asyncio==0.15.1
+async_generator==1.10 ; python_version < '3.7'
+gunicorn==20.1.0
 
 
 # Documentation

tests/middleware/test_logging.py

@@ -154,3 +154,43 @@ async def app(scope, receive, send):
             if record.name == "uvicorn.access"
         ]
         assert '"GET / HTTP/1.1" 599' in messages.pop()
+
+
+@pytest.mark.asyncio
+@pytest.mark.parametrize(
+    "access_log_format,expected_output",
+    [
+        # TODO: add more tests
+        ("access: %(h)s", "access: 127.0.0.1"),
+        ('access: "%({test-request-header}i)s"', 'access: "request-header-val"'),
+        ('access: "%({test-response-header}o)s"', 'access: "response-header-val"'),
+    ],
+)
+async def test_access_log_format(access_log_format, expected_output, caplog):
+    async def app(scope, receive, send):  # pragma: no cover
+        assert scope["type"] == "http"
+        await send(
+            {
+                "type": "http.response.start",
+                "status": 204,
+                "headers": [(b"test-response-header", b"response-header-val")],
+            }
+        )
+        await send({"type": "http.response.body", "body": b"", "more_body": False})
+
+    config = Config(app=app, access_log_format=access_log_format)
+    with caplog_for_logger(caplog, "uvicorn.access"):
+        async with run_server(config):
+            async with httpx.AsyncClient() as client:
+                response = await client.get(
+                    "http://127.0.0.1:8000",
+                    headers={"test-request-header": "request-header-val"},
+                )
+        assert response.status_code == 204
+
+    access_log_messages = [
+        record.message for record in caplog.records if "uvicorn.access" in record.name
+    ]
+
+    assert len(access_log_messages) == 1
+    assert access_log_messages[0] == expected_output

tests/protocols/test_utils.py

@@ -1,8 +1,14 @@
 import socket
+import time
 
 import pytest
 
-from uvicorn.protocols.utils import get_client_addr, get_local_addr, get_remote_addr
+from uvicorn.protocols.utils import (
+    RequestResponseTiming,
+    get_client_addr,
+    get_local_addr,
+    get_remote_addr,
+)
 
 
 class MockSocket:
@@ -91,3 +97,51 @@ def test_get_remote_addr():
 )
 def test_get_client_addr(scope, expected_client):
     assert get_client_addr(scope) == expected_client
+
+
+def test_request_response_timing_request_duration_seconds():
+    timing = RequestResponseTiming()
+    with pytest.raises(ValueError):
+        timing.request_duration_seconds()
+
+    timing.request_started()
+    with pytest.raises(ValueError):
+        timing.request_duration_seconds()
+
+    # Make sure time.monotonic is updated before calls (caused problems in
+    # windows tests)
+    time.sleep(0.02)
+    timing.request_ended()
+    assert timing.request_duration_seconds() > 0
+
+
+def test_request_response_timing_response_duration_seconds():
+    timing = RequestResponseTiming()
+    with pytest.raises(ValueError):
+        timing.response_duration_seconds()
+
+    timing.response_started()
+    with pytest.raises(ValueError):
+        timing.response_duration_seconds()
+
+    # Make sure time.monotonic is updated before calls (caused problems in
+    # windows tests)
+    time.sleep(0.02)
+    timing.response_ended()
+    assert timing.response_duration_seconds() > 0
+
+
+def test_request_response_timing_total_duration_seconds():
+    timing = RequestResponseTiming()
+    with pytest.raises(ValueError):
+        timing.total_duration_seconds()
+
+    timing.request_started()
+    with pytest.raises(ValueError):
+        timing.total_duration_seconds()
+
+    # Make sure time.monotonic is updated before calls (caused problems in
+    # windows tests)
+    time.sleep(0.02)
+    timing.response_ended()
+    assert timing.total_duration_seconds() > 0

tests/test_gunicorn_worker.py

@@ -0,0 +1,87 @@
+import random
+import re
+import signal
+import subprocess
+import sys
+import time
+
+import pytest
+import requests
+
+
+# XXX: copypaste from test_main
+# Exclude from coverage, because this code is executed in subprocess.
+async def app(scope, receive, send):  # pragma: no cover
+    assert scope["type"] == "http"
+    await send(
+        {
+            "type": "http.response.start",
+            "status": 204,
+            "headers": [(b"test-response-header", b"response-header-val")],
+        }
+    )
+    await send({"type": "http.response.body", "body": b"", "more_body": False})
+
+
+@pytest.mark.xfail(
+    sys.platform == "win32", reason="gunicorn process doesn't start on windows?"
+)
+@pytest.mark.parametrize(
+    "worker_class",
+    [
+        "uvicorn.workers.UvicornWorker",
+        "uvicorn.workers.UvicornH11Worker",
+    ],
+)
+def test_gunicorn_worker_stdout_access_log_format(worker_class):
+    random_port = random.randint(1024, 49151)
+    access_logformat = (
+        'hellotest %(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s"'
+        ' "%(a)s" %(L)s "%({test-request-header}i)s"'
+        ' "%({test-response-header}o)s"'
+    )
+    process = subprocess.Popen(
+        [
+            "gunicorn",
+            "tests.test_gunicorn_worker:app",
+            "-k=%s" % worker_class,
+            "--bind=127.0.0.1:%d" % random_port,
+            "--access-logfile=-",
+            "--access-logformat=%s" % access_logformat,
+        ],
+        stdout=subprocess.PIPE,
+        stderr=subprocess.PIPE,
+    )
+
+    attempts = 0
+    while True:
+        attempts += 1
+        try:
+            resp = requests.get(
+                "http://127.0.0.1:%d" % random_port,
+                headers={
+                    "Test-Request-Header": "request-header-val",
+                    "User-Agent": "request-user-agent",
+                },
+            )
+        except requests.exceptions.ConnectionError:
+            if attempts > 10:
+                raise
+            time.sleep(0.05)
+        else:
+            break
+
+    assert resp.status_code == 204
+    process.send_signal(signal.SIGTERM)
+    stdout, stderr = process.communicate()
+
+    stdout_lines = stdout.decode().splitlines()
+    if not len(stdout_lines) == 1:
+        pytest.fail("Access log line not found, stderr:\n" + stderr.decode())
+
+    assert re.match(
+        r'hellotest 127\.0\.0\.1 - - \[[^]]+\] "GET / HTTP/1\.1" 204 - "-"'
+        r' "request-user-agent" [0-9.]+ "request-header-val" '
+        '"response-header-val"',
+        stdout_lines[0],
+    )

uvicorn/config.py

@@ -211,6 +211,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,
@@ -284,6 +285,8 @@ def __init__(
         self.encoded_headers: List[Tuple[bytes, bytes]] = []
         self.factory = factory
 
+        self.access_log_format = access_log_format
+
         self.loaded = False
         self.configure_logging()
 
@@ -385,6 +388,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: