Implement gunicorn access log format for httptools impl

issue ref encode#527

Author: immerrr

uvicorn/config.py

@@ -231,6 +231,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
@@ -274,6 +275,8 @@ def __init__(
         self.encoded_headers: List[Tuple[bytes, bytes]] = []
         self.factory = factory
 
+        self.gunicorn_log = gunicorn_log
+
         self.loaded = False
         self.configure_logging()
 

uvicorn/protocols/http/httptools_impl.py

@@ -2,7 +2,10 @@
 import http
 import logging
 import re
+import time
 import urllib
+from collections import abc
+from os import getpid
 from typing import Callable
 
 import httptools
@@ -39,6 +42,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, on_connection_lost: Callable = None, _loop=None
@@ -53,6 +224,7 @@ def __init__(
         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
@@ -211,6 +383,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):
@@ -245,6 +422,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,
@@ -338,6 +516,7 @@ def __init__(
         logger,
         access_logger,
         access_log,
+        gunicorn_log,
         default_headers,
         message_event,
         expect_100_continue,
@@ -350,6 +529,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
@@ -369,6 +549,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:
@@ -415,6 +601,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()
 
@@ -436,7 +625,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),
@@ -511,6 +700,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()

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: