From 8ebe781df7ac47cc627ed7e77242ad9187a8eca5 Mon Sep 17 00:00:00 2001
From: immerrr <immerrr@gmail.com>
Date: Mon, 31 May 2021 16:07:58 +0200
Subject: [PATCH 01/14] Implement gunicorn access log format for httptools impl

issue ref #527
---
 uvicorn/config.py                        |   3 +
 uvicorn/protocols/http/httptools_impl.py | 205 ++++++++++++++++++++++-
 uvicorn/workers.py                       |   1 +
 3 files changed, 207 insertions(+), 2 deletions(-)

diff --git a/uvicorn/config.py b/uvicorn/config.py
index 40a431e80..db37c46a3 100644
--- a/uvicorn/config.py
+++ b/uvicorn/config.py
@@ -240,6 +240,7 @@ def __init__(
         ssl_ciphers: str = "TLSv1",
         headers: Optional[List[List[str]]] = None,
         factory: bool = False,
+        gunicorn_log=None,
     ):
         self.app = app
         self.host = host
@@ -284,6 +285,8 @@ def __init__(
         self.encoded_headers: List[Tuple[bytes, bytes]] = []
         self.factory = factory
 
+        self.gunicorn_log = gunicorn_log
+
         self.loaded = False
         self.configure_logging()
 
diff --git a/uvicorn/protocols/http/httptools_impl.py b/uvicorn/protocols/http/httptools_impl.py
index e6183bbcb..e7bc4639a 100644
--- a/uvicorn/protocols/http/httptools_impl.py
+++ b/uvicorn/protocols/http/httptools_impl.py
@@ -2,8 +2,10 @@
 import http
 import logging
 import re
+import time
 import urllib
-from collections import deque
+from collections import abc, deque
+from os import getpid
 
 import httptools
 
@@ -39,6 +41,174 @@ def _get_status_line(status_code):
 }
 
 
+class GunicornSafeAtoms(abc.Mapping):
+    def __init__(self, scope):
+        self.scope = scope
+        self.status_code = None
+        self.response_headers = {}
+        self.response_length = 0
+
+        self._request_headers = None
+
+    @property
+    def request_headers(self):
+        if self._request_headers is None:
+            self._request_headers = dict(self.scope['headers'])
+        return self._request_headers
+
+    @property
+    def duration(self):
+        duration_extension = self.scope['extensions']['uvicorn_request_duration']
+        d = duration_extension['response_end_time'] - duration_extension['request_start_time']
+        return d
+
+    def on_asgi_message(self, message):
+        if message['type'] == 'http.response.start':
+            self.status_code = message['status']
+            self.response_headers = dict(message['headers'])
+        elif message['type'] == 'http.response.body':
+            self.response_length += len(message.get('body', ''))
+
+    def _request_header(self, key):
+        return self.request_headers.get(key.lower())
+
+    def _response_header(self, key):
+        return self.response_headers.get(key.lower())
+
+    def _wsgi_environ_variable(self, key):
+        # FIXME: provide fallbacks to access WSGI environ (at least the
+        # required variables).
+        return None
+
+    def __getitem__(self, key):
+        if key in self.HANDLERS:
+            retval = self.HANDLERS[key](self)
+        elif key.startswith('{'):
+            if key.endswith('}i'):
+                retval = self._request_header(key[1:-2])
+            elif key.endswith('}o'):
+                retval = self._response_header(key[1:-2])
+            elif key.endswith('}e'):
+                retval = self._wsgi_environ_variable(key[1:-2])
+            else:
+                retval = None
+        else:
+            retval = None
+
+        if retval is None:
+            return '-'
+        if isinstance(retval, str):
+            return retval.replace('"', '\\"')
+        return retval
+
+    HANDLERS = {}
+
+    def _register_handler(key, handlers=HANDLERS):
+        def decorator(fn):
+            handlers[key] = fn
+            return fn
+        return decorator
+
+    @_register_handler('h')
+    def _remote_address(self, *args, **kwargs):
+        return self.scope['client'][0]
+
+    @_register_handler('l')
+    def _dash(self, *args, **kwargs):
+        return '-'
+
+    @_register_handler('u')
+    def _user_name(self, *args, **kwargs):
+        pass
+
+    @_register_handler('t')
+    def date_of_the_request(self, *args, **kwargs):
+        """Date and time in Apache Common Log Format"""
+        return time.strftime('[%d/%b/%Y:%H:%M:%S %z]')
+
+    @_register_handler('r')
+    def status_line(self, *args, **kwargs):
+        full_raw_path = (self.scope['raw_path'] + self.scope['query_string'])
+        full_path = full_raw_path.decode('ascii')
+        return '{method} {full_path} HTTP/{http_version}'.format(
+            full_path=full_path, **self.scope
+        )
+
+    @_register_handler('m')
+    def request_method(self, *args, **kwargs):
+        return self.scope['method']
+
+    @_register_handler('U')
+    def url_path(self, *args, **kwargs):
+        return self.scope['raw_path'].decode('ascii')
+
+    @_register_handler('q')
+    def query_string(self, *args, **kwargs):
+        return self.scope['query_string'].decode('ascii')
+
+    @_register_handler('H')
+    def protocol(self, *args, **kwargs):
+        return 'HTTP/%s' % self.scope['http_version']
+
+    @_register_handler('s')
+    def status(self, *args, **kwargs):
+        return self.status_code or '-'
+
+    @_register_handler('B')
+    def response_length(self, *args, **kwargs):
+        return self.response_length
+
+    @_register_handler('b')
+    def response_length_or_dash(self, *args, **kwargs):
+        return self.response_length or '-'
+
+    @_register_handler('f')
+    def referer(self, *args, **kwargs):
+        val = self.request_headers.get(b'referer')
+        if val is None:
+            return None
+        return val.decode('ascii')
+
+    @_register_handler('a')
+    def user_agent(self, *args, **kwargs):
+        val = self.request_headers.get(b'user-agent')
+        if val is None:
+            return None
+        return val.decode('ascii')
+
+    @_register_handler('T')
+    def request_time_seconds(self, *args, **kwargs):
+        return int(self.duration)
+
+    @_register_handler('D')
+    def request_time_microseconds(self, *args, **kwargs):
+        return int(self.duration * 1_000_000)
+
+    @_register_handler('L')
+    def request_time_decimal_seconds(self, *args, **kwargs):
+        return "%.6f" % self.duration
+
+    @_register_handler('p')
+    def process_id(self, *args, **kwargs):
+        return "<%s>" % getpid()
+
+    def __iter__(self):
+        # FIXME: add WSGI environ
+        yield from self.HANDLERS
+        for k, _ in self.scope['headers']:
+            yield '{%s}i' % k.lower()
+        for k in self.response_headers:
+            yield '{%s}o' % k.lower()
+
+    def __len__(self):
+        # FIXME: add WSGI environ
+        return (
+            len(self.HANDLERS)
+            + len(self.scope['headers'] or ())
+            + len(self.response_headers)
+        )
+
+
 class HttpToolsProtocol(asyncio.Protocol):
     def __init__(self, config, server_state, _loop=None):
         if not config.loaded:
@@ -50,6 +220,7 @@ def __init__(self, config, server_state, _loop=None):
         self.logger = logging.getLogger("uvicorn.error")
         self.access_logger = logging.getLogger("uvicorn.access")
         self.access_log = self.access_logger.hasHandlers()
+        self.gunicorn_log = config.gunicorn_log
         self.parser = httptools.HttpRequestParser(self)
         self.ws_protocol_class = config.ws_protocol_class
         self.root_path = config.root_path
@@ -203,6 +374,11 @@ def on_url(self, url):
             "raw_path": raw_path,
             "query_string": parsed_url.query if parsed_url.query else b"",
             "headers": self.headers,
+            "extensions": {
+                "uvicorn_request_duration": {
+                    "request_start_time": time.monotonic(),
+                }
+            },
         }
 
     def on_header(self, name: bytes, value: bytes):
@@ -237,6 +413,7 @@ def on_headers_complete(self):
             logger=self.logger,
             access_logger=self.access_logger,
             access_log=self.access_log,
+            gunicorn_log=self.gunicorn_log,
             default_headers=self.default_headers,
             message_event=asyncio.Event(),
             expect_100_continue=self.expect_100_continue,
@@ -330,6 +507,7 @@ def __init__(
         logger,
         access_logger,
         access_log,
+        gunicorn_log,
         default_headers,
         message_event,
         expect_100_continue,
@@ -342,6 +520,7 @@ def __init__(
         self.logger = logger
         self.access_logger = access_logger
         self.access_log = access_log
+        self.gunicorn_log = gunicorn_log
         self.default_headers = default_headers
         self.message_event = message_event
         self.on_response = on_response
@@ -361,6 +540,12 @@ def __init__(
         self.chunked_encoding = None
         self.expected_content_length = 0
 
+        # For logging.
+        if self.gunicorn_log:
+            self.gunicorn_atoms = GunicornSafeAtoms(self.scope)
+        else:
+            self.gunicorn_atoms = None
+
     # ASGI exception wrapper
     async def run_asgi(self, app):
         try:
@@ -407,6 +592,9 @@ async def send_500_response(self):
     async def send(self, message):
         message_type = message["type"]
 
+        if self.gunicorn_atoms is not None:
+            self.gunicorn_atoms.on_asgi_message(message)
+
         if self.flow.write_paused and not self.disconnected:
             await self.flow.drain()
 
@@ -428,7 +616,7 @@ 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:
+            if self.access_log and not self.gunicorn_log:
                 self.access_logger.info(
                     '%s - "%s %s HTTP/%s" %d',
                     get_client_addr(self.scope),
@@ -503,6 +691,19 @@ async def send(self, message):
                 if self.expected_content_length != 0:
                     raise RuntimeError("Response content shorter than Content-Length")
                 self.response_complete = True
+                duration_extension = self.scope['extensions']['uvicorn_request_duration']
+                duration_extension['response_end_time'] = time.monotonic()
+
+                if self.gunicorn_log:
+                    try:
+                        self.gunicorn_log.access_log.info(
+                            self.gunicorn_log.cfg.access_log_format,
+                            self.gunicorn_atoms,
+                        )
+                    except:
+                        import traceback
+                        self.gunicorn_log.error(traceback.format_exc())
+
                 self.message_event.set()
                 if not self.keep_alive:
                     self.transport.close()
diff --git a/uvicorn/workers.py b/uvicorn/workers.py
index f28c3a8d4..268149f9b 100644
--- a/uvicorn/workers.py
+++ b/uvicorn/workers.py
@@ -40,6 +40,7 @@ def __init__(self, *args: Any, **kwargs: Any) -> None:
             "callback_notify": self.callback_notify,
             "limit_max_requests": self.max_requests,
             "forwarded_allow_ips": self.cfg.forwarded_allow_ips,
+            'gunicorn_log': self.log,
         }
 
         if self.cfg.is_ssl:

From 409add907feacf12743aee7346e78e03f5175664 Mon Sep 17 00:00:00 2001
From: immerrr <immerrr@gmail.com>
Date: Wed, 3 Feb 2021 10:26:24 +0100
Subject: [PATCH 02/14] Move GunicornSafeAtoms to uvicorn.logging

---
 uvicorn/logging.py                       | 171 +++++++++++++++++++++++
 uvicorn/protocols/http/httptools_impl.py | 171 +----------------------
 2 files changed, 173 insertions(+), 169 deletions(-)

diff --git a/uvicorn/logging.py b/uvicorn/logging.py
index f22ed8d72..091970faa 100644
--- a/uvicorn/logging.py
+++ b/uvicorn/logging.py
@@ -1,7 +1,10 @@
 import http
 import logging
 import sys
+import time
+from collections import abc
 from copy import copy
+from os import getpid
 from typing import Optional
 
 import click
@@ -115,3 +118,171 @@ def formatMessage(self, record: logging.LogRecord) -> str:
             }
         )
         return super().formatMessage(recordcopy)
+
+
+class GunicornSafeAtoms(abc.Mapping):
+    """Implement atoms necessary for gunicorn log."""
+    def __init__(self, scope):
+        self.scope = scope
+        self.status_code = None
+        self.response_headers = {}
+        self.response_length = 0
+
+        self._request_headers = None
+
+    @property
+    def request_headers(self):
+        if self._request_headers is None:
+            self._request_headers = dict(self.scope['headers'])
+        return self._request_headers
+
+    @property
+    def duration(self):
+        d = self.scope['response_end_time'] - self.scope['request_start_time']
+        return d
+
+    def on_asgi_message(self, message):
+        if message['type'] == 'http.response.start':
+            self.status_code = message['status']
+            self.response_headers = dict(message['headers'])
+        elif message['type'] == 'http.response.body':
+            self.response_length += len(message.get('body', ''))
+
+    def _request_header(self, key):
+        return self.request_headers.get(key.lower())
+
+    def _response_header(self, key):
+        return self.response_headers.get(key.lower())
+
+    def _wsgi_environ_variable(self, key):
+        # FIXME: provide fallbacks to access WSGI environ (at least the
+        # required variables).
+        return None
+
+    def __getitem__(self, key):
+        if key in self.HANDLERS:
+            retval = self.HANDLERS[key](self)
+        elif key.startswith('{'):
+            if key.endswith('}i'):
+                retval = self._request_header(key[1:-2])
+            elif key.endswith('}o'):
+                retval = self._response_header(key[1:-2])
+            elif key.endswith('}e'):
+                retval = self._wsgi_environ_variable(key[1:-2])
+            else:
+                retval = None
+        else:
+            retval = None
+
+        if retval is None:
+            return '-'
+        if isinstance(retval, str):
+            return retval.replace('"', '\\"')
+        return retval
+
+    HANDLERS = {}
+
+    def _register_handler(key, handlers=HANDLERS):
+        def decorator(fn):
+            handlers[key] = fn
+            return fn
+        return decorator
+
+    @_register_handler('h')
+    def _remote_address(self, *args, **kwargs):
+        return self.scope['client'][0]
+
+    @_register_handler('l')
+    def _dash(self, *args, **kwargs):
+        return '-'
+
+    @_register_handler('u')
+    def _user_name(self, *args, **kwargs):
+        pass
+
+    @_register_handler('t')
+    def date_of_the_request(self, *args, **kwargs):
+        """Date and time in Apache Common Log Format"""
+        return time.strftime('[%d/%b/%Y:%H:%M:%S %z]')
+
+    @_register_handler('r')
+    def status_line(self, *args, **kwargs):
+        full_raw_path = (self.scope['raw_path'] + self.scope['query_string'])
+        full_path = full_raw_path.decode('ascii')
+        return '{method} {full_path} HTTP/{http_version}'.format(
+            full_path=full_path, **self.scope
+        )
+
+    @_register_handler('m')
+    def request_method(self, *args, **kwargs):
+        return self.scope['method']
+
+    @_register_handler('U')
+    def url_path(self, *args, **kwargs):
+        return self.scope['raw_path'].decode('ascii')
+
+    @_register_handler('q')
+    def query_string(self, *args, **kwargs):
+        return self.scope['query_string'].decode('ascii')
+
+    @_register_handler('H')
+    def protocol(self, *args, **kwargs):
+        return 'HTTP/%s' % self.scope['http_version']
+
+    @_register_handler('s')
+    def status(self, *args, **kwargs):
+        return self.status_code or '-'
+
+    @_register_handler('B')
+    def response_length(self, *args, **kwargs):
+        return self.response_length
+
+    @_register_handler('b')
+    def response_length_or_dash(self, *args, **kwargs):
+        return self.response_length or '-'
+
+    @_register_handler('f')
+    def referer(self, *args, **kwargs):
+        val = self.request_headers.get(b'referer')
+        if val is None:
+            return None
+        return val.decode('ascii')
+
+    @_register_handler('a')
+    def user_agent(self, *args, **kwargs):
+        val = self.request_headers.get(b'user-agent')
+        if val is None:
+            return None
+        return val.decode('ascii')
+
+    @_register_handler('T')
+    def request_time_seconds(self, *args, **kwargs):
+        return int(self.duration)
+
+    @_register_handler('D')
+    def request_time_microseconds(self, *args, **kwargs):
+        return int(self.duration * 1_000_000)
+
+    @_register_handler('L')
+    def request_time_decimal_seconds(self, *args, **kwargs):
+        return "%.6f" % self.duration
+
+    @_register_handler('p')
+    def process_id(self, *args, **kwargs):
+        return "<%s>" % getpid()
+
+    def __iter__(self):
+        # FIXME: add WSGI environ
+        yield from self.HANDLERS
+        for k, _ in self.scope['headers']:
+            yield '{%s}i' % k.lower()
+        for k in self.response_headers:
+            yield '{%s}o' % k.lower()
+
+    def __len__(self):
+        # FIXME: add WSGI environ
+        return (
+            len(self.HANDLERS)
+            + len(self.scope['headers'] or ())
+            + len(self.response_headers)
+        )
diff --git a/uvicorn/protocols/http/httptools_impl.py b/uvicorn/protocols/http/httptools_impl.py
index e7bc4639a..6d612461c 100644
--- a/uvicorn/protocols/http/httptools_impl.py
+++ b/uvicorn/protocols/http/httptools_impl.py
@@ -3,13 +3,14 @@
 import logging
 import re
 import time
+import traceback
 import urllib
 from collections import abc, deque
 from os import getpid
 
 import httptools
 
-from uvicorn.logging import TRACE_LOG_LEVEL
+from uvicorn.logging import TRACE_LOG_LEVEL, GunicornSafeAtoms
 from uvicorn.protocols.http.flow_control import (
     CLOSE_HEADER,
     HIGH_WATER_LIMIT,
@@ -41,174 +42,6 @@ def _get_status_line(status_code):
 }
 
 
-class GunicornSafeAtoms(abc.Mapping):
-    def __init__(self, scope):
-        self.scope = scope
-        self.status_code = None
-        self.response_headers = {}
-        self.response_length = 0
-
-        self._request_headers = None
-
-    @property
-    def request_headers(self):
-        if self._request_headers is None:
-            self._request_headers = dict(self.scope['headers'])
-        return self._request_headers
-
-    @property
-    def duration(self):
-        duration_extension = self.scope['extensions']['uvicorn_request_duration']
-        d = duration_extension['response_end_time'] - duration_extension['request_start_time']
-        return d
-
-    def on_asgi_message(self, message):
-        if message['type'] == 'http.response.start':
-            self.status_code = message['status']
-            self.response_headers = dict(message['headers'])
-        elif message['type'] == 'http.response.body':
-            self.response_length += len(message.get('body', ''))
-
-    def _request_header(self, key):
-        return self.request_headers.get(key.lower())
-
-    def _response_header(self, key):
-        return self.response_headers.get(key.lower())
-
-    def _wsgi_environ_variable(self, key):
-        # FIXME: provide fallbacks to access WSGI environ (at least the
-        # required variables).
-        return None
-
-    def __getitem__(self, key):
-        if key in self.HANDLERS:
-            retval = self.HANDLERS[key](self)
-        elif key.startswith('{'):
-            if key.endswith('}i'):
-                retval = self._request_header(key[1:-2])
-            elif key.endswith('}o'):
-                retval = self._response_header(key[1:-2])
-            elif key.endswith('}e'):
-                retval = self._wsgi_environ_variable(key[1:-2])
-            else:
-                retval = None
-        else:
-            retval = None
-
-        if retval is None:
-            return '-'
-        if isinstance(retval, str):
-            return retval.replace('"', '\\"')
-        return retval
-
-    HANDLERS = {}
-
-    def _register_handler(key, handlers=HANDLERS):
-        def decorator(fn):
-            handlers[key] = fn
-            return fn
-        return decorator
-
-    @_register_handler('h')
-    def _remote_address(self, *args, **kwargs):
-        return self.scope['client'][0]
-
-    @_register_handler('l')
-    def _dash(self, *args, **kwargs):
-        return '-'
-
-    @_register_handler('u')
-    def _user_name(self, *args, **kwargs):
-        pass
-
-    @_register_handler('t')
-    def date_of_the_request(self, *args, **kwargs):
-        """Date and time in Apache Common Log Format"""
-        return time.strftime('[%d/%b/%Y:%H:%M:%S %z]')
-
-    @_register_handler('r')
-    def status_line(self, *args, **kwargs):
-        full_raw_path = (self.scope['raw_path'] + self.scope['query_string'])
-        full_path = full_raw_path.decode('ascii')
-        return '{method} {full_path} HTTP/{http_version}'.format(
-            full_path=full_path, **self.scope
-        )
-
-    @_register_handler('m')
-    def request_method(self, *args, **kwargs):
-        return self.scope['method']
-
-    @_register_handler('U')
-    def url_path(self, *args, **kwargs):
-        return self.scope['raw_path'].decode('ascii')
-
-    @_register_handler('q')
-    def query_string(self, *args, **kwargs):
-        return self.scope['query_string'].decode('ascii')
-
-    @_register_handler('H')
-    def protocol(self, *args, **kwargs):
-        return 'HTTP/%s' % self.scope['http_version']
-
-    @_register_handler('s')
-    def status(self, *args, **kwargs):
-        return self.status_code or '-'
-
-    @_register_handler('B')
-    def response_length(self, *args, **kwargs):
-        return self.response_length
-
-    @_register_handler('b')
-    def response_length_or_dash(self, *args, **kwargs):
-        return self.response_length or '-'
-
-    @_register_handler('f')
-    def referer(self, *args, **kwargs):
-        val = self.request_headers.get(b'referer')
-        if val is None:
-            return None
-        return val.decode('ascii')
-
-    @_register_handler('a')
-    def user_agent(self, *args, **kwargs):
-        val = self.request_headers.get(b'user-agent')
-        if val is None:
-            return None
-        return val.decode('ascii')
-
-    @_register_handler('T')
-    def request_time_seconds(self, *args, **kwargs):
-        return int(self.duration)
-
-    @_register_handler('D')
-    def request_time_microseconds(self, *args, **kwargs):
-        return int(self.duration * 1_000_000)
-
-    @_register_handler('L')
-    def request_time_decimal_seconds(self, *args, **kwargs):
-        return "%.6f" % self.duration
-
-    @_register_handler('p')
-    def process_id(self, *args, **kwargs):
-        return "<%s>" % getpid()
-
-    def __iter__(self):
-        # FIXME: add WSGI environ
-        yield from self.HANDLERS
-        for k, _ in self.scope['headers']:
-            yield '{%s}i' % k.lower()
-        for k in self.response_headers:
-            yield '{%s}o' % k.lower()
-
-    def __len__(self):
-        # FIXME: add WSGI environ
-        return (
-            len(self.HANDLERS)
-            + len(self.scope['headers'] or ())
-            + len(self.response_headers)
-        )
-
-
 class HttpToolsProtocol(asyncio.Protocol):
     def __init__(self, config, server_state, _loop=None):
         if not config.loaded:

From 769d3f906b3579be7c714ae5b0f6d2bb284bf036 Mon Sep 17 00:00:00 2001
From: immerrr <immerrr@gmail.com>
Date: Mon, 31 May 2021 16:11:05 +0200
Subject: [PATCH 03/14] Enable gunicorn logging for h11 impl

---
 uvicorn/protocols/http/h11_impl.py       | 35 ++++++++++++++++++++++--
 uvicorn/protocols/http/httptools_impl.py | 13 ++++-----
 2 files changed, 39 insertions(+), 9 deletions(-)

diff --git a/uvicorn/protocols/http/h11_impl.py b/uvicorn/protocols/http/h11_impl.py
index 78e5ffdc1..582ee8d71 100644
--- a/uvicorn/protocols/http/h11_impl.py
+++ b/uvicorn/protocols/http/h11_impl.py
@@ -1,11 +1,13 @@
 import asyncio
 import http
 import logging
+import time
+import traceback
 from urllib.parse import unquote
 
 import h11
 
-from uvicorn.logging import TRACE_LOG_LEVEL
+from uvicorn.logging import TRACE_LOG_LEVEL, GunicornSafeAtoms
 from uvicorn.protocols.http.flow_control import (
     CLOSE_HEADER,
     HIGH_WATER_LIMIT,
@@ -164,6 +166,11 @@ def handle_events(self):
                     "raw_path": raw_path,
                     "query_string": query_string,
                     "headers": self.headers,
+                    "extensions": {
+                        "uvicorn_request_duration": {
+                            "request_start_time": time.monotonic(),
+                        }
+                    },
                 }
 
                 for name, value in self.headers:
@@ -192,6 +199,7 @@ def handle_events(self):
                     logger=self.logger,
                     access_logger=self.access_logger,
                     access_log=self.access_log,
+                    gunicorn_log=self.config.gunicorn_log,
                     default_headers=self.default_headers,
                     message_event=asyncio.Event(),
                     on_response=self.on_response_complete,
@@ -330,6 +338,7 @@ def __init__(
         logger,
         access_logger,
         access_log,
+        gunicorn_log,
         default_headers,
         message_event,
         on_response,
@@ -341,6 +350,7 @@ def __init__(
         self.logger = logger
         self.access_logger = access_logger
         self.access_log = access_log
+        self.gunicorn_log = gunicorn_log
         self.default_headers = default_headers
         self.message_event = message_event
         self.on_response = on_response
@@ -358,6 +368,12 @@ def __init__(
         self.response_started = False
         self.response_complete = False
 
+        # For logging
+        if self.gunicorn_log:
+            self.gunicorn_atoms = GunicornSafeAtoms(self.scope)
+        else:
+            self.gunicorn_atoms = None
+
     # ASGI exception wrapper
     async def run_asgi(self, app):
         try:
@@ -410,6 +426,9 @@ async def send(self, message):
         if self.disconnected:
             return
 
+        if self.gunicorn_atoms is not None:
+            self.gunicorn_atoms.on_asgi_message(message)
+
         if not self.response_started:
             # Sending response status line and headers
             if message_type != "http.response.start":
@@ -425,7 +444,7 @@ 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:
+            if self.access_log and self.gunicorn_log is None:
                 self.access_logger.info(
                     '%s - "%s %s HTTP/%s" %d',
                     get_client_addr(self.scope),
@@ -466,6 +485,18 @@ async def send(self, message):
                 self.message_event.set()
                 event = h11.EndOfMessage()
                 output = self.conn.send(event)
+
+                duration_extension = self.scope['extensions']['uvicorn_request_duration']
+                duration_extension["response_end_time"] = time.monotonic()
+                if self.gunicorn_log is not None:
+                    try:
+                        self.gunicorn_log.access_log.info(
+                            self.gunicorn_log.cfg.access_log_format,
+                            self.gunicorn_atoms,
+                        )
+                    except:  # noqa
+                        self.gunicorn_log.error(traceback.format_exc())
+
                 self.transport.write(output)
 
         else:
diff --git a/uvicorn/protocols/http/httptools_impl.py b/uvicorn/protocols/http/httptools_impl.py
index 6d612461c..63850b603 100644
--- a/uvicorn/protocols/http/httptools_impl.py
+++ b/uvicorn/protocols/http/httptools_impl.py
@@ -425,15 +425,15 @@ async def send_500_response(self):
     async def send(self, message):
         message_type = message["type"]
 
-        if self.gunicorn_atoms is not None:
-            self.gunicorn_atoms.on_asgi_message(message)
-
         if self.flow.write_paused and not self.disconnected:
             await self.flow.drain()
 
         if self.disconnected:
             return
 
+        if self.gunicorn_atoms is not None:
+            self.gunicorn_atoms.on_asgi_message(message)
+
         if not self.response_started:
             # Sending response status line and headers
             if message_type != "http.response.start":
@@ -449,7 +449,7 @@ 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 and not self.gunicorn_log:
+            if self.access_log and self.gunicorn_log is None:
                 self.access_logger.info(
                     '%s - "%s %s HTTP/%s" %d',
                     get_client_addr(self.scope),
@@ -527,14 +527,13 @@ async def send(self, message):
                 duration_extension = self.scope['extensions']['uvicorn_request_duration']
                 duration_extension['response_end_time'] = time.monotonic()
 
-                if self.gunicorn_log:
+                if self.gunicorn_log is not None:
                     try:
                         self.gunicorn_log.access_log.info(
                             self.gunicorn_log.cfg.access_log_format,
                             self.gunicorn_atoms,
                         )
-                    except:
-                        import traceback
+                    except:  # noqa
                         self.gunicorn_log.error(traceback.format_exc())
 
                 self.message_event.set()

From ecfe25d8a81c1e29abc17032343cc5ae599a0b5a Mon Sep 17 00:00:00 2001
From: immerrr <immerrr@gmail.com>
Date: Wed, 3 Feb 2021 10:38:03 +0100
Subject: [PATCH 04/14] Decode request/response headers

---
 uvicorn/logging.py | 10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)

diff --git a/uvicorn/logging.py b/uvicorn/logging.py
index 091970faa..345ecc873 100644
--- a/uvicorn/logging.py
+++ b/uvicorn/logging.py
@@ -133,7 +133,10 @@ def __init__(self, scope):
     @property
     def request_headers(self):
         if self._request_headers is None:
-            self._request_headers = dict(self.scope['headers'])
+            self._request_headers = {
+                k.decode('ascii'): v.decode('ascii')
+                for k, v in self.scope['headers']
+            }
         return self._request_headers
 
     @property
@@ -144,7 +147,10 @@ def duration(self):
     def on_asgi_message(self, message):
         if message['type'] == 'http.response.start':
             self.status_code = message['status']
-            self.response_headers = dict(message['headers'])
+            self.response_headers = {
+                k.decode('ascii'): v.decode('ascii')
+                for k, v in message['headers']
+            }
         elif message['type'] == 'http.response.body':
             self.response_length += len(message.get('body', ''))
 

From dbcc940f567e3320c4c69fd3439a594e4575612d Mon Sep 17 00:00:00 2001
From: immerrr <immerrr@gmail.com>
Date: Wed, 3 Feb 2021 16:53:13 +0100
Subject: [PATCH 05/14] Make linter happy

---
 uvicorn/logging.py                       | 113 ++++++++++++-----------
 uvicorn/protocols/http/h11_impl.py       |   4 +-
 uvicorn/protocols/http/httptools_impl.py |   7 +-
 uvicorn/workers.py                       |   2 +-
 4 files changed, 66 insertions(+), 60 deletions(-)

diff --git a/uvicorn/logging.py b/uvicorn/logging.py
index 345ecc873..de1a9e9bf 100644
--- a/uvicorn/logging.py
+++ b/uvicorn/logging.py
@@ -121,7 +121,15 @@ def formatMessage(self, record: logging.LogRecord) -> str:
 
 
 class GunicornSafeAtoms(abc.Mapping):
-    """Implement atoms necessary for gunicorn log."""
+    """Implement atoms necessary for gunicorn log.
+
+    This class does a few things:
+    - provide all atoms necessary for gunicorn log formatter
+    - collect response body size for reporting from ASGI messages
+    - provide mapping interface that returns '-' for missing atoms
+    - escapes double quotes found in atom strings
+    """
+
     def __init__(self, scope):
         self.scope = scope
         self.status_code = None
@@ -134,25 +142,23 @@ def __init__(self, scope):
     def request_headers(self):
         if self._request_headers is None:
             self._request_headers = {
-                k.decode('ascii'): v.decode('ascii')
-                for k, v in self.scope['headers']
+                k.decode("ascii"): v.decode("ascii") for k, v in self.scope["headers"]
             }
         return self._request_headers
 
     @property
     def duration(self):
-        d = self.scope['response_end_time'] - self.scope['request_start_time']
+        d = self.scope["response_end_time"] - self.scope["request_start_time"]
         return d
 
     def on_asgi_message(self, message):
-        if message['type'] == 'http.response.start':
-            self.status_code = message['status']
+        if message["type"] == "http.response.start":
+            self.status_code = message["status"]
             self.response_headers = {
-                k.decode('ascii'): v.decode('ascii')
-                for k, v in message['headers']
+                k.decode("ascii"): v.decode("ascii") for k, v in message["headers"]
             }
-        elif message['type'] == 'http.response.body':
-            self.response_length += len(message.get('body', ''))
+        elif message["type"] == "http.response.body":
+            self.response_length += len(message.get("body", ""))
 
     def _request_header(self, key):
         return self.request_headers.get(key.lower())
@@ -168,12 +174,12 @@ def _wsgi_environ_variable(self, key):
     def __getitem__(self, key):
         if key in self.HANDLERS:
             retval = self.HANDLERS[key](self)
-        elif key.startswith('{'):
-            if key.endswith('}i'):
+        elif key.startswith("{"):
+            if key.endswith("}i"):
                 retval = self._request_header(key[1:-2])
-            elif key.endswith('}o'):
+            elif key.endswith("}o"):
                 retval = self._response_header(key[1:-2])
-            elif key.endswith('}e'):
+            elif key.endswith("}e"):
                 retval = self._wsgi_environ_variable(key[1:-2])
             else:
                 retval = None
@@ -181,7 +187,7 @@ def __getitem__(self, key):
             retval = None
 
         if retval is None:
-            return '-'
+            return "-"
         if isinstance(retval, str):
             return retval.replace('"', '\\"')
         return retval
@@ -192,103 +198,104 @@ def _register_handler(key, handlers=HANDLERS):
         def decorator(fn):
             handlers[key] = fn
             return fn
+
         return decorator
 
-    @_register_handler('h')
+    @_register_handler("h")
     def _remote_address(self, *args, **kwargs):
-        return self.scope['client'][0]
+        return self.scope["client"][0]
 
-    @_register_handler('l')
+    @_register_handler("l")
     def _dash(self, *args, **kwargs):
-        return '-'
+        return "-"
 
-    @_register_handler('u')
+    @_register_handler("u")
     def _user_name(self, *args, **kwargs):
         pass
 
-    @_register_handler('t')
+    @_register_handler("t")
     def date_of_the_request(self, *args, **kwargs):
         """Date and time in Apache Common Log Format"""
-        return time.strftime('[%d/%b/%Y:%H:%M:%S %z]')
+        return time.strftime("[%d/%b/%Y:%H:%M:%S %z]")
 
-    @_register_handler('r')
+    @_register_handler("r")
     def status_line(self, *args, **kwargs):
-        full_raw_path = (self.scope['raw_path'] + self.scope['query_string'])
-        full_path = full_raw_path.decode('ascii')
-        return '{method} {full_path} HTTP/{http_version}'.format(
+        full_raw_path = self.scope["raw_path"] + self.scope["query_string"]
+        full_path = full_raw_path.decode("ascii")
+        return "{method} {full_path} HTTP/{http_version}".format(
             full_path=full_path, **self.scope
         )
 
-    @_register_handler('m')
+    @_register_handler("m")
     def request_method(self, *args, **kwargs):
-        return self.scope['method']
+        return self.scope["method"]
 
-    @_register_handler('U')
+    @_register_handler("U")
     def url_path(self, *args, **kwargs):
-        return self.scope['raw_path'].decode('ascii')
+        return self.scope["raw_path"].decode("ascii")
 
-    @_register_handler('q')
+    @_register_handler("q")
     def query_string(self, *args, **kwargs):
-        return self.scope['query_string'].decode('ascii')
+        return self.scope["query_string"].decode("ascii")
 
-    @_register_handler('H')
+    @_register_handler("H")
     def protocol(self, *args, **kwargs):
-        return 'HTTP/%s' % self.scope['http_version']
+        return "HTTP/%s" % self.scope["http_version"]
 
-    @_register_handler('s')
+    @_register_handler("s")
     def status(self, *args, **kwargs):
-        return self.status_code or '-'
+        return self.status_code or "-"
 
-    @_register_handler('B')
+    @_register_handler("B")
     def response_length(self, *args, **kwargs):
         return self.response_length
 
-    @_register_handler('b')
+    @_register_handler("b")
     def response_length_or_dash(self, *args, **kwargs):
-        return self.response_length or '-'
+        return self.response_length or "-"
 
-    @_register_handler('f')
+    @_register_handler("f")
     def referer(self, *args, **kwargs):
-        val = self.request_headers.get(b'referer')
+        val = self.request_headers.get(b"referer")
         if val is None:
             return None
-        return val.decode('ascii')
+        return val.decode("ascii")
 
-    @_register_handler('a')
+    @_register_handler("a")
     def user_agent(self, *args, **kwargs):
-        val = self.request_headers.get(b'user-agent')
+        val = self.request_headers.get(b"user-agent")
         if val is None:
             return None
-        return val.decode('ascii')
+        return val.decode("ascii")
 
-    @_register_handler('T')
+    @_register_handler("T")
     def request_time_seconds(self, *args, **kwargs):
         return int(self.duration)
 
-    @_register_handler('D')
+    @_register_handler("D")
     def request_time_microseconds(self, *args, **kwargs):
         return int(self.duration * 1_000_000)
 
-    @_register_handler('L')
+    @_register_handler("L")
     def request_time_decimal_seconds(self, *args, **kwargs):
         return "%.6f" % self.duration
 
-    @_register_handler('p')
+    @_register_handler("p")
     def process_id(self, *args, **kwargs):
         return "<%s>" % getpid()
 
     def __iter__(self):
         # FIXME: add WSGI environ
         yield from self.HANDLERS
-        for k, _ in self.scope['headers']:
-            yield '{%s}i' % k.lower()
+        for k, _ in self.scope["headers"]:
+            yield "{%s}i" % k.lower()
         for k in self.response_headers:
-            yield '{%s}o' % k.lower()
+            yield "{%s}o" % k.lower()
 
     def __len__(self):
         # FIXME: add WSGI environ
         return (
             len(self.HANDLERS)
-            + len(self.scope['headers'] or ())
+            + len(self.scope["headers"] or ())
             + len(self.response_headers)
         )
diff --git a/uvicorn/protocols/http/h11_impl.py b/uvicorn/protocols/http/h11_impl.py
index 582ee8d71..4e4f741fe 100644
--- a/uvicorn/protocols/http/h11_impl.py
+++ b/uvicorn/protocols/http/h11_impl.py
@@ -486,8 +486,8 @@ async def send(self, message):
                 event = h11.EndOfMessage()
                 output = self.conn.send(event)
 
-                duration_extension = self.scope['extensions']['uvicorn_request_duration']
-                duration_extension["response_end_time"] = time.monotonic()
+                duration_scope = self.scope["extensions"]["uvicorn_request_duration"]
+                duration_scope["response_end_time"] = time.monotonic()
                 if self.gunicorn_log is not None:
                     try:
                         self.gunicorn_log.access_log.info(
diff --git a/uvicorn/protocols/http/httptools_impl.py b/uvicorn/protocols/http/httptools_impl.py
index 63850b603..da935047d 100644
--- a/uvicorn/protocols/http/httptools_impl.py
+++ b/uvicorn/protocols/http/httptools_impl.py
@@ -5,8 +5,7 @@
 import time
 import traceback
 import urllib
-from collections import abc, deque
-from os import getpid
+from collections import deque
 
 import httptools
 
@@ -524,8 +523,8 @@ async def send(self, message):
                 if self.expected_content_length != 0:
                     raise RuntimeError("Response content shorter than Content-Length")
                 self.response_complete = True
-                duration_extension = self.scope['extensions']['uvicorn_request_duration']
-                duration_extension['response_end_time'] = time.monotonic()
+                duration_scope = self.scope["extensions"]["uvicorn_request_duration"]
+                duration_scope["response_end_time"] = time.monotonic()
 
                 if self.gunicorn_log is not None:
                     try:
diff --git a/uvicorn/workers.py b/uvicorn/workers.py
index 268149f9b..beb599e49 100644
--- a/uvicorn/workers.py
+++ b/uvicorn/workers.py
@@ -40,7 +40,7 @@ def __init__(self, *args: Any, **kwargs: Any) -> None:
             "callback_notify": self.callback_notify,
             "limit_max_requests": self.max_requests,
             "forwarded_allow_ips": self.cfg.forwarded_allow_ips,
-            'gunicorn_log': self.log,
+            "gunicorn_log": self.log,
         }
 
         if self.cfg.is_ssl:

From 23d7221de0bb1b59b42b71eaaa8e8435e097e7a5 Mon Sep 17 00:00:00 2001
From: immerrr <immerrr@gmail.com>
Date: Mon, 14 Jun 2021 12:11:45 +0200
Subject: [PATCH 06/14] Add minimal test for gunicorn logging

---
 requirements.txt              |  2 +
 tests/test_gunicorn_worker.py | 78 +++++++++++++++++++++++++++++++++++
 2 files changed, 80 insertions(+)
 create mode 100644 tests/test_gunicorn_worker.py

diff --git a/requirements.txt b/requirements.txt
index ecf2a4348..2f12911a1 100644
--- a/requirements.txt
+++ b/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
diff --git a/tests/test_gunicorn_worker.py b/tests/test_gunicorn_worker.py
new file mode 100644
index 000000000..c9257a2dc
--- /dev/null
+++ b/tests/test_gunicorn_worker.py
@@ -0,0 +1,78 @@
+import random
+import re
+import signal
+import subprocess
+import time
+
+import pytest
+import requests
+
+
+# XXX: copypaste from test_main
+async def app(scope, receive, send):
+    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.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"},
+            )
+        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' [0-9.]+ "request-header-val" "response-header-val"',
+        stdout_lines[0],
+    )

From 55176408bdf30e388432f188c90c84db60d7a5df Mon Sep 17 00:00:00 2001
From: immerrr <immerrr@gmail.com>
Date: Mon, 14 Jun 2021 12:16:05 +0200
Subject: [PATCH 07/14] Replace asgi "extension" with RequestResponseTiming
 class

---
 uvicorn/logging.py                       |  6 ++---
 uvicorn/protocols/http/h11_impl.py       | 16 ++++++-------
 uvicorn/protocols/http/httptools_impl.py | 19 ++++++++-------
 uvicorn/protocols/utils.py               | 30 ++++++++++++++++++++++++
 4 files changed, 51 insertions(+), 20 deletions(-)

diff --git a/uvicorn/logging.py b/uvicorn/logging.py
index de1a9e9bf..4aa32ab46 100644
--- a/uvicorn/logging.py
+++ b/uvicorn/logging.py
@@ -130,8 +130,9 @@ class GunicornSafeAtoms(abc.Mapping):
     - escapes double quotes found in atom strings
     """
 
-    def __init__(self, scope):
+    def __init__(self, scope, timing):
         self.scope = scope
+        self.timing = timing
         self.status_code = None
         self.response_headers = {}
         self.response_length = 0
@@ -148,8 +149,7 @@ def request_headers(self):
 
     @property
     def duration(self):
-        d = self.scope["response_end_time"] - self.scope["request_start_time"]
-        return d
+        return self.timing.total_duration_seconds()
 
     def on_asgi_message(self, message):
         if message["type"] == "http.response.start":
diff --git a/uvicorn/protocols/http/h11_impl.py b/uvicorn/protocols/http/h11_impl.py
index 4e4f741fe..c55a7b524 100644
--- a/uvicorn/protocols/http/h11_impl.py
+++ b/uvicorn/protocols/http/h11_impl.py
@@ -1,7 +1,6 @@
 import asyncio
 import http
 import logging
-import time
 import traceback
 from urllib.parse import unquote
 
@@ -15,6 +14,7 @@
     service_unavailable,
 )
 from uvicorn.protocols.utils import (
+    RequestResponseTiming,
     get_client_addr,
     get_local_addr,
     get_path_with_query_string,
@@ -166,11 +166,6 @@ def handle_events(self):
                     "raw_path": raw_path,
                     "query_string": query_string,
                     "headers": self.headers,
-                    "extensions": {
-                        "uvicorn_request_duration": {
-                            "request_start_time": time.monotonic(),
-                        }
-                    },
                 }
 
                 for name, value in self.headers:
@@ -204,6 +199,7 @@ def handle_events(self):
                     message_event=asyncio.Event(),
                     on_response=self.on_response_complete,
                 )
+                self.cycle.timing.request_started()
                 task = self.loop.create_task(self.cycle.run_asgi(app))
                 task.add_done_callback(self.tasks.discard)
                 self.tasks.add(task)
@@ -221,6 +217,7 @@ def handle_events(self):
                     self.transport.resume_reading()
                     self.conn.start_next_cycle()
                     continue
+                self.cycle.timing.request_ended()
                 self.cycle.more_body = False
                 self.cycle.message_event.set()
 
@@ -367,10 +364,11 @@ def __init__(
         # Response state
         self.response_started = False
         self.response_complete = False
+        self.timing = RequestResponseTiming()
 
         # For logging
         if self.gunicorn_log:
-            self.gunicorn_atoms = GunicornSafeAtoms(self.scope)
+            self.gunicorn_atoms = GunicornSafeAtoms(self.scope, self.timing)
         else:
             self.gunicorn_atoms = None
 
@@ -437,6 +435,7 @@ async def send(self, message):
 
             self.response_started = True
             self.waiting_for_100_continue = False
+            self.timing.response_started()
 
             status_code = message["status"]
             headers = self.default_headers + message.get("headers", [])
@@ -486,8 +485,7 @@ async def send(self, message):
                 event = h11.EndOfMessage()
                 output = self.conn.send(event)
 
-                duration_scope = self.scope["extensions"]["uvicorn_request_duration"]
-                duration_scope["response_end_time"] = time.monotonic()
+                self.timing.response_ended()
                 if self.gunicorn_log is not None:
                     try:
                         self.gunicorn_log.access_log.info(
diff --git a/uvicorn/protocols/http/httptools_impl.py b/uvicorn/protocols/http/httptools_impl.py
index da935047d..bda223671 100644
--- a/uvicorn/protocols/http/httptools_impl.py
+++ b/uvicorn/protocols/http/httptools_impl.py
@@ -17,6 +17,7 @@
     service_unavailable,
 )
 from uvicorn.protocols.utils import (
+    RequestResponseTiming,
     get_client_addr,
     get_local_addr,
     get_path_with_query_string,
@@ -82,6 +83,7 @@ def __init__(self, config, server_state, _loop=None):
         self.headers = None
         self.expect_100_continue = False
         self.cycle = None
+        self.request_start_time = None
 
     # Protocol interface
     def connection_made(self, transport):
@@ -206,13 +208,11 @@ def on_url(self, url):
             "raw_path": raw_path,
             "query_string": parsed_url.query if parsed_url.query else b"",
             "headers": self.headers,
-            "extensions": {
-                "uvicorn_request_duration": {
-                    "request_start_time": time.monotonic(),
-                }
-            },
         }
 
+    def on_message_begin(self):
+        self.request_start_time = time.monotonic()
+
     def on_header(self, name: bytes, value: bytes):
         name = name.lower()
         if name == b"expect" and value.lower() == b"100-continue":
@@ -252,6 +252,7 @@ def on_headers_complete(self):
             keep_alive=http_version != "1.0",
             on_response=self.on_response_complete,
         )
+        self.cycle.timing.request_start_time = self.request_start_time
         if existing_cycle is None or existing_cycle.response_complete:
             # Standard case - start processing the request.
             task = self.loop.create_task(self.cycle.run_asgi(app))
@@ -275,6 +276,7 @@ def on_message_complete(self):
             return
         self.cycle.more_body = False
         self.cycle.message_event.set()
+        self.cycle.timing.request_ended()
 
     def on_response_complete(self):
         # Callback for pipelined HTTP requests to be started.
@@ -371,10 +373,11 @@ def __init__(
         self.response_complete = False
         self.chunked_encoding = None
         self.expected_content_length = 0
+        self.timing = RequestResponseTiming()
 
         # For logging.
         if self.gunicorn_log:
-            self.gunicorn_atoms = GunicornSafeAtoms(self.scope)
+            self.gunicorn_atoms = GunicornSafeAtoms(self.scope, self.timing)
         else:
             self.gunicorn_atoms = None
 
@@ -440,6 +443,7 @@ async def send(self, message):
                 raise RuntimeError(msg % message_type)
 
             self.response_started = True
+            self.timing.response_started()
             self.waiting_for_100_continue = False
 
             status_code = message["status"]
@@ -523,8 +527,7 @@ async def send(self, message):
                 if self.expected_content_length != 0:
                     raise RuntimeError("Response content shorter than Content-Length")
                 self.response_complete = True
-                duration_scope = self.scope["extensions"]["uvicorn_request_duration"]
-                duration_scope["response_end_time"] = time.monotonic()
+                self.timing.response_ended()
 
                 if self.gunicorn_log is not None:
                     try:
diff --git a/uvicorn/protocols/utils.py b/uvicorn/protocols/utils.py
index 1da733600..ffd48aff6 100644
--- a/uvicorn/protocols/utils.py
+++ b/uvicorn/protocols/utils.py
@@ -1,4 +1,5 @@
 import asyncio
+import time
 import urllib.parse
 from typing import Optional, Tuple
 
@@ -52,3 +53,32 @@ def get_path_with_query_string(scope: WWWScope) -> str:
             path_with_query_string, scope["query_string"].decode("ascii")
         )
     return path_with_query_string
+
+
+class RequestResponseTiming:
+    def __init__(self):
+        self.request_start_time: Optional[int] = None
+        self.request_end_time: Optional[int] = None
+        self.response_start_time: Optional[int] = None
+        self.response_end_time: Optional[int] = None
+
+    def request_started(self):
+        self.request_start_time = time.monotonic()
+
+    def request_ended(self):
+        self.request_end_time = time.monotonic()
+
+    def response_started(self):
+        self.response_start_time = time.monotonic()
+
+    def response_ended(self):
+        self.response_end_time = time.monotonic()
+
+    def request_duration_seconds(self):
+        return self.request_end_time - self.request_start_time
+
+    def response_duration_seconds(self):
+        return self.response_end_time - self.response_start_time
+
+    def total_duration_seconds(self):
+        return self.response_end_time - self.request_start_time

From f4e513d8b0888f0cb388ff5ebe3c2a983c572fe3 Mon Sep 17 00:00:00 2001
From: immerrr <immerrr@gmail.com>
Date: Sun, 20 Jun 2021 11:07:37 +0200
Subject: [PATCH 08/14] Add type annotations, fix couple of bugs

---
 tests/test_gunicorn_worker.py            |   5 +-
 uvicorn/logging.py                       | 123 +++++++++++++----------
 uvicorn/protocols/http/httptools_impl.py |   2 +-
 uvicorn/protocols/utils.py               |  66 ++++++++----
 4 files changed, 117 insertions(+), 79 deletions(-)

diff --git a/tests/test_gunicorn_worker.py b/tests/test_gunicorn_worker.py
index c9257a2dc..3014cea7d 100644
--- a/tests/test_gunicorn_worker.py
+++ b/tests/test_gunicorn_worker.py
@@ -72,7 +72,8 @@ def test_gunicorn_worker_stdout_access_log_format(worker_class):
         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' [0-9.]+ "request-header-val" "response-header-val"',
+        r'hellotest 127\.0\.0\.1 - - \[[^]]+\] "GET / HTTP/1\.1" 204 - "-"'
+        r' "python-requests/2.25.1" [0-9.]+ "request-header-val" '
+        '"response-header-val"',
         stdout_lines[0],
     )
diff --git a/uvicorn/logging.py b/uvicorn/logging.py
index 4aa32ab46..aa0b02792 100644
--- a/uvicorn/logging.py
+++ b/uvicorn/logging.py
@@ -2,13 +2,17 @@
 import logging
 import sys
 import time
+import typing
 from collections import abc
 from copy import copy
 from os import getpid
-from typing import Optional
+from typing import Any, Callable, Dict, Iterator, Optional
 
 import click
 
+if typing.TYPE_CHECKING:
+    import uvicorn.protocols.utils
+
 TRACE_LOG_LEVEL = 5
 
 
@@ -130,17 +134,19 @@ class GunicornSafeAtoms(abc.Mapping):
     - escapes double quotes found in atom strings
     """
 
-    def __init__(self, scope, timing):
+    def __init__(
+        self, scope: dict, timing: "uvicorn.protocols.utils.RequestResponseTiming"
+    ):
         self.scope = scope
         self.timing = timing
         self.status_code = None
-        self.response_headers = {}
-        self.response_length = 0
+        self.response_headers: Dict[str, str] = {}
+        self._response_length = 0
 
-        self._request_headers = None
+        self._request_headers: Optional[Dict[str, str]] = None
 
     @property
-    def request_headers(self):
+    def request_headers(self) -> Dict[str, str]:
         if self._request_headers is None:
             self._request_headers = {
                 k.decode("ascii"): v.decode("ascii") for k, v in self.scope["headers"]
@@ -148,30 +154,39 @@ def request_headers(self):
         return self._request_headers
 
     @property
-    def duration(self):
+    def duration(self) -> float:
         return self.timing.total_duration_seconds()
 
-    def on_asgi_message(self, message):
+    def on_asgi_message(self, message: Dict[str, Any]) -> None:
         if message["type"] == "http.response.start":
             self.status_code = message["status"]
             self.response_headers = {
                 k.decode("ascii"): v.decode("ascii") for k, v in message["headers"]
             }
         elif message["type"] == "http.response.body":
-            self.response_length += len(message.get("body", ""))
+            self._response_length += len(message.get("body", ""))
 
-    def _request_header(self, key):
+    def _request_header(self, key: str) -> Optional[str]:
         return self.request_headers.get(key.lower())
 
-    def _response_header(self, key):
+    def _response_header(self, key: str) -> Optional[str]:
         return self.response_headers.get(key.lower())
 
-    def _wsgi_environ_variable(self, key):
+    def _wsgi_environ_variable(self, key: str) -> None:
         # FIXME: provide fallbacks to access WSGI environ (at least the
         # required variables).
-        return None
+        raise NotImplementedError
 
-    def __getitem__(self, key):
+    @classmethod
+    def _log_format_atom(cls, val: Optional[str]) -> str:
+        if val is None:
+            return "-"
+        if isinstance(val, str):
+            return val.replace('"', '\\"')
+        return val
+
+    def __getitem__(self, key: str) -> str:
+        retval: Optional[str]
         if key in self.HANDLERS:
             retval = self.HANDLERS[key](self)
         elif key.startswith("{"):
@@ -180,46 +195,50 @@ def __getitem__(self, key):
             elif key.endswith("}o"):
                 retval = self._response_header(key[1:-2])
             elif key.endswith("}e"):
-                retval = self._wsgi_environ_variable(key[1:-2])
+                # retval = self._wsgi_environ_variable(key[1:-2])
+                raise NotImplementedError("WSGI environ not supported")
             else:
                 retval = None
         else:
             retval = None
+        return self._log_format_atom(retval)
 
-        if retval is None:
-            return "-"
-        if isinstance(retval, str):
-            return retval.replace('"', '\\"')
-        return retval
+    _LogAtomHandler = Callable[["GunicornSafeAtoms"], Optional[str]]
+    HANDLERS: Dict[str, _LogAtomHandler] = {}
 
-    HANDLERS = {}
+    # mypy does not understand class-member decorators:
+    #
+    # https://github.com/python/mypy/issues/7778
+    def _register_handler(  # type: ignore[misc]
+        key: str, handlers: Dict[str, _LogAtomHandler] = HANDLERS
+    ) -> Callable[[_LogAtomHandler], _LogAtomHandler]:
+        _LogAtomHandler = Callable[["GunicornSafeAtoms"], Optional[str]]
 
-    def _register_handler(key, handlers=HANDLERS):
-        def decorator(fn):
+        def decorator(fn: _LogAtomHandler) -> _LogAtomHandler:
             handlers[key] = fn
             return fn
 
         return decorator
 
     @_register_handler("h")
-    def _remote_address(self, *args, **kwargs):
+    def _remote_address(self) -> Optional[str]:
         return self.scope["client"][0]
 
     @_register_handler("l")
-    def _dash(self, *args, **kwargs):
+    def _dash(self) -> str:
         return "-"
 
     @_register_handler("u")
-    def _user_name(self, *args, **kwargs):
+    def _user_name(self) -> Optional[str]:
         pass
 
     @_register_handler("t")
-    def date_of_the_request(self, *args, **kwargs):
+    def date_of_the_request(self) -> Optional[str]:
         """Date and time in Apache Common Log Format"""
         return time.strftime("[%d/%b/%Y:%H:%M:%S %z]")
 
     @_register_handler("r")
-    def status_line(self, *args, **kwargs):
+    def status_line(self) -> Optional[str]:
         full_raw_path = self.scope["raw_path"] + self.scope["query_string"]
         full_path = full_raw_path.decode("ascii")
         return "{method} {full_path} HTTP/{http_version}".format(
@@ -227,64 +246,58 @@ def status_line(self, *args, **kwargs):
         )
 
     @_register_handler("m")
-    def request_method(self, *args, **kwargs):
+    def request_method(self) -> Optional[str]:
         return self.scope["method"]
 
     @_register_handler("U")
-    def url_path(self, *args, **kwargs):
+    def url_path(self) -> Optional[str]:
         return self.scope["raw_path"].decode("ascii")
 
     @_register_handler("q")
-    def query_string(self, *args, **kwargs):
+    def query_string(self) -> Optional[str]:
         return self.scope["query_string"].decode("ascii")
 
     @_register_handler("H")
-    def protocol(self, *args, **kwargs):
+    def protocol(self) -> Optional[str]:
         return "HTTP/%s" % self.scope["http_version"]
 
     @_register_handler("s")
-    def status(self, *args, **kwargs):
+    def status(self) -> Optional[str]:
         return self.status_code or "-"
 
     @_register_handler("B")
-    def response_length(self, *args, **kwargs):
-        return self.response_length
+    def response_length(self) -> Optional[str]:
+        return str(self._response_length)
 
     @_register_handler("b")
-    def response_length_or_dash(self, *args, **kwargs):
-        return self.response_length or "-"
+    def response_length_or_dash(self) -> Optional[str]:
+        return str(self._response_length or "-")
 
     @_register_handler("f")
-    def referer(self, *args, **kwargs):
-        val = self.request_headers.get(b"referer")
-        if val is None:
-            return None
-        return val.decode("ascii")
+    def referer(self) -> Optional[str]:
+        return self.request_headers.get("referer")
 
     @_register_handler("a")
-    def user_agent(self, *args, **kwargs):
-        val = self.request_headers.get(b"user-agent")
-        if val is None:
-            return None
-        return val.decode("ascii")
+    def user_agent(self) -> Optional[str]:
+        return self.request_headers.get("user-agent")
 
     @_register_handler("T")
-    def request_time_seconds(self, *args, **kwargs):
-        return int(self.duration)
+    def request_time_seconds(self) -> Optional[str]:
+        return str(int(self.duration))
 
     @_register_handler("D")
-    def request_time_microseconds(self, *args, **kwargs):
-        return int(self.duration * 1_000_000)
+    def request_time_microseconds(self) -> str:
+        return str(int(self.duration * 1_000_000))
 
     @_register_handler("L")
-    def request_time_decimal_seconds(self, *args, **kwargs):
+    def request_time_decimal_seconds(self) -> str:
         return "%.6f" % self.duration
 
     @_register_handler("p")
-    def process_id(self, *args, **kwargs):
+    def process_id(self) -> str:
         return "<%s>" % getpid()
 
-    def __iter__(self):
+    def __iter__(self) -> Iterator[str]:
         # FIXME: add WSGI environ
         yield from self.HANDLERS
         for k, _ in self.scope["headers"]:
@@ -292,7 +305,7 @@ def __iter__(self):
         for k in self.response_headers:
             yield "{%s}o" % k.lower()
 
-    def __len__(self):
+    def __len__(self) -> int:
         # FIXME: add WSGI environ
         return (
             len(self.HANDLERS)
diff --git a/uvicorn/protocols/http/httptools_impl.py b/uvicorn/protocols/http/httptools_impl.py
index bda223671..2a47b7aea 100644
--- a/uvicorn/protocols/http/httptools_impl.py
+++ b/uvicorn/protocols/http/httptools_impl.py
@@ -252,7 +252,7 @@ def on_headers_complete(self):
             keep_alive=http_version != "1.0",
             on_response=self.on_response_complete,
         )
-        self.cycle.timing.request_start_time = self.request_start_time
+        self.cycle.timing._request_start_time = self.request_start_time
         if existing_cycle is None or existing_cycle.response_complete:
             # Standard case - start processing the request.
             task = self.loop.create_task(self.cycle.run_asgi(app))
diff --git a/uvicorn/protocols/utils.py b/uvicorn/protocols/utils.py
index ffd48aff6..c9343bbb2 100644
--- a/uvicorn/protocols/utils.py
+++ b/uvicorn/protocols/utils.py
@@ -56,29 +56,53 @@ def get_path_with_query_string(scope: WWWScope) -> str:
 
 
 class RequestResponseTiming:
-    def __init__(self):
-        self.request_start_time: Optional[int] = None
-        self.request_end_time: Optional[int] = None
-        self.response_start_time: Optional[int] = None
-        self.response_end_time: Optional[int] = None
-
-    def request_started(self):
-        self.request_start_time = time.monotonic()
-
-    def request_ended(self):
-        self.request_end_time = time.monotonic()
-
-    def response_started(self):
-        self.response_start_time = time.monotonic()
-
-    def response_ended(self):
-        self.response_end_time = time.monotonic()
-
-    def request_duration_seconds(self):
+    def __init__(self) -> None:
+        self._request_start_time: Optional[float] = None
+        self._request_end_time: Optional[float] = None
+        self._response_start_time: Optional[float] = None
+        self._response_end_time: Optional[float] = None
+
+    def request_started(self) -> None:
+        self._request_start_time = time.monotonic()
+
+    @property
+    def request_start_time(self) -> float:
+        if self._request_start_time is None:
+            raise ValueError("request_started() was not called")
+        return self._request_start_time
+
+    def request_ended(self) -> None:
+        self._request_end_time = time.monotonic()
+
+    @property
+    def request_end_time(self) -> float:
+        if self._request_end_time is None:
+            raise ValueError("request_ended() was not called")
+        return self._request_end_time
+
+    def response_started(self) -> None:
+        self._response_start_time = time.monotonic()
+
+    @property
+    def response_start_time(self) -> float:
+        if self._response_start_time is None:
+            raise ValueError("response_started() was not called")
+        return self._response_start_time
+
+    def response_ended(self) -> None:
+        self._response_end_time = time.monotonic()
+
+    @property
+    def response_end_time(self) -> float:
+        if self._response_end_time is None:
+            raise ValueError("response_ended() was not called")
+        return self._response_end_time
+
+    def request_duration_seconds(self) -> float:
         return self.request_end_time - self.request_start_time
 
-    def response_duration_seconds(self):
+    def response_duration_seconds(self) -> float:
         return self.response_end_time - self.response_start_time
 
-    def total_duration_seconds(self):
+    def total_duration_seconds(self) -> float:
         return self.response_end_time - self.request_start_time

From 93191fdec5d43ccd2d66a6f56b5ce00daed130d8 Mon Sep 17 00:00:00 2001
From: immerrr <immerrr@gmail.com>
Date: Sun, 20 Jun 2021 17:47:26 +0200
Subject: [PATCH 09/14] Make coverage pass: exclude log atoms from coverage,
 add some tests

---
 tests/protocols/test_utils.py | 56 ++++++++++++++++++++++++++++++++++-
 tests/test_gunicorn_worker.py |  7 ++++-
 uvicorn/logging.py            |  2 +-
 uvicorn/protocols/utils.py    |  5 ++++
 4 files changed, 67 insertions(+), 3 deletions(-)

diff --git a/tests/protocols/test_utils.py b/tests/protocols/test_utils.py
index 50889ab68..5913dcc24 100644
--- a/tests/protocols/test_utils.py
+++ b/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
diff --git a/tests/test_gunicorn_worker.py b/tests/test_gunicorn_worker.py
index 3014cea7d..ec6382a39 100644
--- a/tests/test_gunicorn_worker.py
+++ b/tests/test_gunicorn_worker.py
@@ -2,6 +2,7 @@
 import re
 import signal
 import subprocess
+import sys
 import time
 
 import pytest
@@ -9,7 +10,8 @@
 
 
 # XXX: copypaste from test_main
-async def app(scope, receive, send):
+# 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(
         {
@@ -21,6 +23,9 @@ async def app(scope, receive, send):
     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",
     [
diff --git a/uvicorn/logging.py b/uvicorn/logging.py
index aa0b02792..a27db6a34 100644
--- a/uvicorn/logging.py
+++ b/uvicorn/logging.py
@@ -124,7 +124,7 @@ def formatMessage(self, record: logging.LogRecord) -> str:
         return super().formatMessage(recordcopy)
 
 
-class GunicornSafeAtoms(abc.Mapping):
+class GunicornSafeAtoms(abc.Mapping):  # pragma: no cover
     """Implement atoms necessary for gunicorn log.
 
     This class does a few things:
diff --git a/uvicorn/protocols/utils.py b/uvicorn/protocols/utils.py
index c9343bbb2..072edebb0 100644
--- a/uvicorn/protocols/utils.py
+++ b/uvicorn/protocols/utils.py
@@ -56,6 +56,11 @@ def get_path_with_query_string(scope: WWWScope) -> str:
 
 
 class RequestResponseTiming:
+    # XXX: switch to "time.perf_counter" because apparently on windows
+    # time.monotonis is using GetTickCount64 which has ~15ms resolution (it
+    # caused problems in tests on windows)
+    #
+    # ref: https://github.com/python-trio/trio/issues/33#issue-202432431
     def __init__(self) -> None:
         self._request_start_time: Optional[float] = None
         self._request_end_time: Optional[float] = None

From 8146e712d285b19dcaa7d2e9570603d1b63c076a Mon Sep 17 00:00:00 2001
From: immerrr <immerrr@gmail.com>
Date: Mon, 21 Jun 2021 18:09:04 +0200
Subject: [PATCH 10/14] Make access_log_format more generic (not dependent on
 gunicorn_log)

---
 uvicorn/config.py                        |  4 +-
 uvicorn/logging.py                       | 19 ++++----
 uvicorn/protocols/http/h11_impl.py       | 55 +++++++++++-------------
 uvicorn/protocols/http/httptools_impl.py | 55 +++++++++++-------------
 uvicorn/workers.py                       |  2 +-
 5 files changed, 65 insertions(+), 70 deletions(-)

diff --git a/uvicorn/config.py b/uvicorn/config.py
index db37c46a3..df7e4e246 100644
--- a/uvicorn/config.py
+++ b/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,
@@ -240,7 +241,6 @@ def __init__(
         ssl_ciphers: str = "TLSv1",
         headers: Optional[List[List[str]]] = None,
         factory: bool = False,
-        gunicorn_log=None,
     ):
         self.app = app
         self.host = host
@@ -285,7 +285,7 @@ def __init__(
         self.encoded_headers: List[Tuple[bytes, bytes]] = []
         self.factory = factory
 
-        self.gunicorn_log = gunicorn_log
+        self.access_log_format = access_log_format
 
         self.loaded = False
         self.configure_logging()
diff --git a/uvicorn/logging.py b/uvicorn/logging.py
index a27db6a34..71678fda9 100644
--- a/uvicorn/logging.py
+++ b/uvicorn/logging.py
@@ -124,14 +124,14 @@ def formatMessage(self, record: logging.LogRecord) -> str:
         return super().formatMessage(recordcopy)
 
 
-class GunicornSafeAtoms(abc.Mapping):  # pragma: no cover
-    """Implement atoms necessary for gunicorn log.
+class AccessLogFields(abc.Mapping):  # pragma: no cover
+    """Container to provide fields for access logging.
 
     This class does a few things:
-    - provide all atoms necessary for gunicorn log formatter
-    - collect response body size for reporting from ASGI messages
-    - provide mapping interface that returns '-' for missing atoms
-    - escapes double quotes found in atom strings
+    - provide all fields necessary for access log formatter
+    - collect info from ASGI messages (status_code/headers/response body size)
+    - provide mapping interface that returns '-' for missing fields
+    - escape double quotes found in fields strings
     """
 
     def __init__(
@@ -161,7 +161,8 @@ def on_asgi_message(self, message: Dict[str, Any]) -> None:
         if message["type"] == "http.response.start":
             self.status_code = message["status"]
             self.response_headers = {
-                k.decode("ascii"): v.decode("ascii") for k, v in message["headers"]
+                k.decode("ascii"): v.decode("ascii")
+                for k, v in message.get("headers") or {}
             }
         elif message["type"] == "http.response.body":
             self._response_length += len(message.get("body", ""))
@@ -203,7 +204,7 @@ def __getitem__(self, key: str) -> str:
             retval = None
         return self._log_format_atom(retval)
 
-    _LogAtomHandler = Callable[["GunicornSafeAtoms"], Optional[str]]
+    _LogAtomHandler = Callable[["AccessLogFields"], Optional[str]]
     HANDLERS: Dict[str, _LogAtomHandler] = {}
 
     # mypy does not understand class-member decorators:
@@ -212,7 +213,7 @@ def __getitem__(self, key: str) -> str:
     def _register_handler(  # type: ignore[misc]
         key: str, handlers: Dict[str, _LogAtomHandler] = HANDLERS
     ) -> Callable[[_LogAtomHandler], _LogAtomHandler]:
-        _LogAtomHandler = Callable[["GunicornSafeAtoms"], Optional[str]]
+        _LogAtomHandler = Callable[["AccessLogFields"], Optional[str]]
 
         def decorator(fn: _LogAtomHandler) -> _LogAtomHandler:
             handlers[key] = fn
diff --git a/uvicorn/protocols/http/h11_impl.py b/uvicorn/protocols/http/h11_impl.py
index c55a7b524..1061c63ba 100644
--- a/uvicorn/protocols/http/h11_impl.py
+++ b/uvicorn/protocols/http/h11_impl.py
@@ -6,7 +6,7 @@
 
 import h11
 
-from uvicorn.logging import TRACE_LOG_LEVEL, GunicornSafeAtoms
+from uvicorn.logging import TRACE_LOG_LEVEL, AccessLogFields
 from uvicorn.protocols.http.flow_control import (
     CLOSE_HEADER,
     HIGH_WATER_LIMIT,
@@ -194,7 +194,7 @@ def handle_events(self):
                     logger=self.logger,
                     access_logger=self.access_logger,
                     access_log=self.access_log,
-                    gunicorn_log=self.config.gunicorn_log,
+                    access_log_format=self.config.access_log_format,
                     default_headers=self.default_headers,
                     message_event=asyncio.Event(),
                     on_response=self.on_response_complete,
@@ -335,7 +335,7 @@ def __init__(
         logger,
         access_logger,
         access_log,
-        gunicorn_log,
+        access_log_format,
         default_headers,
         message_event,
         on_response,
@@ -347,7 +347,7 @@ def __init__(
         self.logger = logger
         self.access_logger = access_logger
         self.access_log = access_log
-        self.gunicorn_log = gunicorn_log
+        self.access_log_format = access_log_format
         self.default_headers = default_headers
         self.message_event = message_event
         self.on_response = on_response
@@ -367,10 +367,7 @@ def __init__(
         self.timing = RequestResponseTiming()
 
         # For logging
-        if self.gunicorn_log:
-            self.gunicorn_atoms = GunicornSafeAtoms(self.scope, self.timing)
-        else:
-            self.gunicorn_atoms = None
+        self.access_log_fields = AccessLogFields(self.scope, self.timing)
 
     # ASGI exception wrapper
     async def run_asgi(self, app):
@@ -424,8 +421,8 @@ async def send(self, message):
         if self.disconnected:
             return
 
-        if self.gunicorn_atoms is not None:
-            self.gunicorn_atoms.on_asgi_message(message)
+        if self.access_log_fields is not None:
+            self.access_log_fields.on_asgi_message(message)
 
         if not self.response_started:
             # Sending response status line and headers
@@ -443,16 +440,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 and self.gunicorn_log is None:
-                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(
@@ -484,18 +471,28 @@ async def send(self, message):
                 self.message_event.set()
                 event = h11.EndOfMessage()
                 output = self.conn.send(event)
+                self.transport.write(output)
 
                 self.timing.response_ended()
-                if self.gunicorn_log is not None:
-                    try:
-                        self.gunicorn_log.access_log.info(
-                            self.gunicorn_log.cfg.access_log_format,
-                            self.gunicorn_atoms,
-                        )
-                    except:  # noqa
-                        self.gunicorn_log.error(traceback.format_exc())
 
-                self.transport.write(output)
+                if self.access_log:
+                    if self.access_log_format is None:
+                        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"],
+                            self.access_log_fields.status_code,
+                        )
+                    else:
+                        try:
+                            self.access_logger.info(
+                                self.access_log_format,
+                                self.access_log_fields,
+                            )
+                        except:  # noqa
+                            self.logger.error(traceback.format_exc())
 
         else:
             # Response already sent
diff --git a/uvicorn/protocols/http/httptools_impl.py b/uvicorn/protocols/http/httptools_impl.py
index 2a47b7aea..971dbb794 100644
--- a/uvicorn/protocols/http/httptools_impl.py
+++ b/uvicorn/protocols/http/httptools_impl.py
@@ -9,7 +9,7 @@
 
 import httptools
 
-from uvicorn.logging import TRACE_LOG_LEVEL, GunicornSafeAtoms
+from uvicorn.logging import TRACE_LOG_LEVEL, AccessLogFields
 from uvicorn.protocols.http.flow_control import (
     CLOSE_HEADER,
     HIGH_WATER_LIMIT,
@@ -53,7 +53,7 @@ def __init__(self, config, server_state, _loop=None):
         self.logger = logging.getLogger("uvicorn.error")
         self.access_logger = logging.getLogger("uvicorn.access")
         self.access_log = self.access_logger.hasHandlers()
-        self.gunicorn_log = config.gunicorn_log
+        self.access_log_format = config.access_log_format
         self.parser = httptools.HttpRequestParser(self)
         self.ws_protocol_class = config.ws_protocol_class
         self.root_path = config.root_path
@@ -245,7 +245,7 @@ def on_headers_complete(self):
             logger=self.logger,
             access_logger=self.access_logger,
             access_log=self.access_log,
-            gunicorn_log=self.gunicorn_log,
+            access_log_format=self.access_log_format,
             default_headers=self.default_headers,
             message_event=asyncio.Event(),
             expect_100_continue=self.expect_100_continue,
@@ -341,7 +341,7 @@ def __init__(
         logger,
         access_logger,
         access_log,
-        gunicorn_log,
+        access_log_format,
         default_headers,
         message_event,
         expect_100_continue,
@@ -354,7 +354,7 @@ def __init__(
         self.logger = logger
         self.access_logger = access_logger
         self.access_log = access_log
-        self.gunicorn_log = gunicorn_log
+        self.access_log_format = access_log_format
         self.default_headers = default_headers
         self.message_event = message_event
         self.on_response = on_response
@@ -376,10 +376,7 @@ def __init__(
         self.timing = RequestResponseTiming()
 
         # For logging.
-        if self.gunicorn_log:
-            self.gunicorn_atoms = GunicornSafeAtoms(self.scope, self.timing)
-        else:
-            self.gunicorn_atoms = None
+        self.access_log_fields = AccessLogFields(self.scope, self.timing)
 
     # ASGI exception wrapper
     async def run_asgi(self, app):
@@ -433,8 +430,7 @@ async def send(self, message):
         if self.disconnected:
             return
 
-        if self.gunicorn_atoms is not None:
-            self.gunicorn_atoms.on_asgi_message(message)
+        self.access_log_fields.on_asgi_message(message)
 
         if not self.response_started:
             # Sending response status line and headers
@@ -452,16 +448,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 and self.gunicorn_log is None:
-                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
             content = [STATUS_LINE[status_code]]
 
@@ -529,16 +515,27 @@ async def send(self, message):
                 self.response_complete = True
                 self.timing.response_ended()
 
-                if self.gunicorn_log is not None:
-                    try:
-                        self.gunicorn_log.access_log.info(
-                            self.gunicorn_log.cfg.access_log_format,
-                            self.gunicorn_atoms,
+                self.message_event.set()
+
+                if self.access_log:
+                    if self.access_log_format is None:
+                        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"],
+                            self.access_log_fields.status_code,
                         )
-                    except:  # noqa
-                        self.gunicorn_log.error(traceback.format_exc())
+                    else:
+                        try:
+                            self.access_logger.info(
+                                self.access_log_format,
+                                self.access_log_fields,
+                            )
+                        except:  # noqa
+                            self.logger.error(traceback.format_exc())
 
-                self.message_event.set()
                 if not self.keep_alive:
                     self.transport.close()
                 self.on_response()
diff --git a/uvicorn/workers.py b/uvicorn/workers.py
index beb599e49..440436c80 100644
--- a/uvicorn/workers.py
+++ b/uvicorn/workers.py
@@ -40,7 +40,7 @@ def __init__(self, *args: Any, **kwargs: Any) -> None:
             "callback_notify": self.callback_notify,
             "limit_max_requests": self.max_requests,
             "forwarded_allow_ips": self.cfg.forwarded_allow_ips,
-            "gunicorn_log": self.log,
+            "access_log_format": self.log.cfg.access_log_format,
         }
 
         if self.cfg.is_ssl:

From f2f322bb0f63473a86853c2539602687c82bbf16 Mon Sep 17 00:00:00 2001
From: immerrr <immerrr@gmail.com>
Date: Mon, 21 Jun 2021 19:38:04 +0200
Subject: [PATCH 11/14] Add --access-log-format parameter to uvicorn itself

---
 docs/deployment.md               |  2 ++
 docs/index.md                    |  2 ++
 tests/middleware/test_logging.py | 40 ++++++++++++++++++++++++++++++++
 uvicorn/config.py                |  4 ++++
 uvicorn/logging.py               |  2 ++
 uvicorn/main.py                  |  8 +++++++
 6 files changed, 58 insertions(+)

diff --git a/docs/deployment.md b/docs/deployment.md
index 60d1af763..a7a1656e4 100644
--- a/docs/deployment.md
+++ b/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        Access log format (supports same fields as
+                                  gunicorn).
   --use-colors / --no-use-colors  Enable/Disable colorized logging.
   --proxy-headers / --no-proxy-headers
                                   Enable/Disable X-Forwarded-Proto,
diff --git a/docs/index.md b/docs/index.md
index 6f57b098a..d7159792b 100644
--- a/docs/index.md
+++ b/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        Access log format (supports same fields as
+                                  gunicorn).
   --use-colors / --no-use-colors  Enable/Disable colorized logging.
   --proxy-headers / --no-proxy-headers
                                   Enable/Disable X-Forwarded-Proto,
diff --git a/tests/middleware/test_logging.py b/tests/middleware/test_logging.py
index 8b8cbd29b..0c675a030 100644
--- a/tests/middleware/test_logging.py
+++ b/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
diff --git a/uvicorn/config.py b/uvicorn/config.py
index df7e4e246..7c0602757 100644
--- a/uvicorn/config.py
+++ b/uvicorn/config.py
@@ -388,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:
diff --git a/uvicorn/logging.py b/uvicorn/logging.py
index 71678fda9..60d7e982c 100644
--- a/uvicorn/logging.py
+++ b/uvicorn/logging.py
@@ -102,6 +102,8 @@ def default(code: int) -> str:
         return status_and_phrase
 
     def formatMessage(self, record: logging.LogRecord) -> str:
+        if len(record.args) != 5:
+            return super().formatMessage(record)
         recordcopy = copy(record)
         (
             client_addr,
diff --git a/uvicorn/main.py b/uvicorn/main.py
index cd853b613..49b49c7f6 100644
--- a/uvicorn/main.py
+++ b/uvicorn/main.py
@@ -202,6 +202,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="Access log format (supports same fields as gunicorn).",
+)
 @click.option(
     "--use-colors/--no-use-colors",
     is_flag=True,
@@ -365,6 +371,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,
@@ -403,6 +410,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,

From 7f7f7f23c1ae863b94a6b4ca3d08a86fa76a143b Mon Sep 17 00:00:00 2001
From: immerrr <immerrr@gmail.com>
Date: Mon, 21 Jun 2021 19:38:04 +0200
Subject: [PATCH 12/14] Update --access-log-format parameter documentation

---
 docs/deployment.md | 4 ++--
 docs/index.md      | 4 ++--
 uvicorn/main.py    | 2 +-
 3 files changed, 5 insertions(+), 5 deletions(-)

diff --git a/docs/deployment.md b/docs/deployment.md
index a7a1656e4..013cafa58 100644
--- a/docs/deployment.md
+++ b/docs/deployment.md
@@ -74,8 +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        Access log format (supports same fields as
-                                  gunicorn).
+  --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,
diff --git a/docs/index.md b/docs/index.md
index d7159792b..87325580c 100644
--- a/docs/index.md
+++ b/docs/index.md
@@ -143,8 +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        Access log format (supports same fields as
-                                  gunicorn).
+  --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,
diff --git a/uvicorn/main.py b/uvicorn/main.py
index 49b49c7f6..492f3b0f7 100644
--- a/uvicorn/main.py
+++ b/uvicorn/main.py
@@ -206,7 +206,7 @@ def print_version(ctx: click.Context, param: click.Parameter, value: bool) -> No
     "--access-log-format",
     type=str,
     default=None,
-    help="Access log format (supports same fields as gunicorn).",
+    help="Log format for access logger, check documentation for details",
 )
 @click.option(
     "--use-colors/--no-use-colors",

From b1cab5fce73f7a8dbe2956a19e19165e9899be81 Mon Sep 17 00:00:00 2001
From: immerrr <immerrr@gmail.com>
Date: Wed, 25 Aug 2021 16:48:52 +0200
Subject: [PATCH 13/14] Update test to not depend on the version of "requests"
 package

---
 tests/test_gunicorn_worker.py | 7 +++++--
 1 file changed, 5 insertions(+), 2 deletions(-)

diff --git a/tests/test_gunicorn_worker.py b/tests/test_gunicorn_worker.py
index ec6382a39..a7d632106 100644
--- a/tests/test_gunicorn_worker.py
+++ b/tests/test_gunicorn_worker.py
@@ -59,7 +59,10 @@ def test_gunicorn_worker_stdout_access_log_format(worker_class):
         try:
             resp = requests.get(
                 "http://127.0.0.1:%d" % random_port,
-                headers={"Test-Request-Header": "request-header-val"},
+                headers={
+                    "Test-Request-Header": "request-header-val",
+                    "User-Agent": "request-user-agent",
+                },
             )
         except requests.exceptions.ConnectionError:
             if attempts > 10:
@@ -78,7 +81,7 @@ def test_gunicorn_worker_stdout_access_log_format(worker_class):
 
     assert re.match(
         r'hellotest 127\.0\.0\.1 - - \[[^]]+\] "GET / HTTP/1\.1" 204 - "-"'
-        r' "python-requests/2.25.1" [0-9.]+ "request-header-val" '
+        r' "request-user-agent" [0-9.]+ "request-header-val" '
         '"response-header-val"',
         stdout_lines[0],
     )

From cd9861beb422b794ca2ce54d6370746e00d9e575 Mon Sep 17 00:00:00 2001
From: immerrr <immerrr@gmail.com>
Date: Fri, 12 Nov 2021 18:21:10 +0100
Subject: [PATCH 14/14] First stab at the documentation

---
 docs/settings.md | 22 +++++++++++++++++++++-
 1 file changed, 21 insertions(+), 1 deletion(-)

diff --git a/docs/settings.md b/docs/settings.md
index 3edf4b3c3..c719caa35 100644
--- a/docs/settings.md
+++ b/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