diff --git a/uvicorn/config.py b/uvicorn/config.py index 86245057f0..1a0d2a80b7 100644 --- a/uvicorn/config.py +++ b/uvicorn/config.py @@ -162,6 +162,7 @@ def __init__( ssl_ciphers="TLSv1", headers=None, factory=False, + gunicorn_log=None, ): self.app = app self.host = host @@ -201,6 +202,8 @@ def __init__( self.encoded_headers = None # type: 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 5f0bc864b3..9eaef66263 100644 --- a/uvicorn/protocols/http/httptools_impl.py +++ b/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 @@ -205,6 +377,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): @@ -239,6 +416,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, @@ -332,6 +510,7 @@ def __init__( logger, access_logger, access_log, + gunicorn_log, default_headers, message_event, expect_100_continue, @@ -344,6 +523,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 @@ -363,6 +543,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: @@ -409,6 +595,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() @@ -430,7 +619,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), @@ -505,6 +694,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 4ffe2ebd94..acbcfdf5bb 100644 --- a/uvicorn/workers.py +++ b/uvicorn/workers.py @@ -38,6 +38,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: