diff --git a/docs/deployment.md b/docs/deployment.md index 60d1af763..013cafa58 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 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 6f57b098a..87325580c 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 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/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 ` - 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 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/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/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 new file mode 100644 index 000000000..a7d632106 --- /dev/null +++ b/tests/test_gunicorn_worker.py @@ -0,0 +1,87 @@ +import random +import re +import signal +import subprocess +import sys +import time + +import pytest +import requests + + +# XXX: copypaste from test_main +# Exclude from coverage, because this code is executed in subprocess. +async def app(scope, receive, send): # pragma: no cover + assert scope["type"] == "http" + await send( + { + "type": "http.response.start", + "status": 204, + "headers": [(b"test-response-header", b"response-header-val")], + } + ) + await send({"type": "http.response.body", "body": b"", "more_body": False}) + + +@pytest.mark.xfail( + sys.platform == "win32", reason="gunicorn process doesn't start on windows?" +) +@pytest.mark.parametrize( + "worker_class", + [ + "uvicorn.workers.UvicornWorker", + "uvicorn.workers.UvicornH11Worker", + ], +) +def test_gunicorn_worker_stdout_access_log_format(worker_class): + random_port = random.randint(1024, 49151) + access_logformat = ( + 'hellotest %(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s"' + ' "%(a)s" %(L)s "%({test-request-header}i)s"' + ' "%({test-response-header}o)s"' + ) + process = subprocess.Popen( + [ + "gunicorn", + "tests.test_gunicorn_worker:app", + "-k=%s" % worker_class, + "--bind=127.0.0.1:%d" % random_port, + "--access-logfile=-", + "--access-logformat=%s" % access_logformat, + ], + stdout=subprocess.PIPE, + stderr=subprocess.PIPE, + ) + + attempts = 0 + while True: + attempts += 1 + try: + resp = requests.get( + "http://127.0.0.1:%d" % random_port, + headers={ + "Test-Request-Header": "request-header-val", + "User-Agent": "request-user-agent", + }, + ) + except requests.exceptions.ConnectionError: + if attempts > 10: + raise + time.sleep(0.05) + else: + break + + assert resp.status_code == 204 + process.send_signal(signal.SIGTERM) + stdout, stderr = process.communicate() + + stdout_lines = stdout.decode().splitlines() + if not len(stdout_lines) == 1: + pytest.fail("Access log line not found, stderr:\n" + stderr.decode()) + + assert re.match( + r'hellotest 127\.0\.0\.1 - - \[[^]]+\] "GET / HTTP/1\.1" 204 - "-"' + r' "request-user-agent" [0-9.]+ "request-header-val" ' + '"response-header-val"', + stdout_lines[0], + ) diff --git a/uvicorn/config.py b/uvicorn/config.py index 40a431e80..7c0602757 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, @@ -284,6 +285,8 @@ def __init__( self.encoded_headers: List[Tuple[bytes, bytes]] = [] self.factory = factory + self.access_log_format = access_log_format + self.loaded = False self.configure_logging() @@ -385,6 +388,10 @@ def configure_logging(self) -> None: self.log_config["formatters"]["access"][ "use_colors" ] = self.use_colors + if self.access_log_format: + self.log_config["formatters"]["access"][ + "fmt" + ] = "%(levelprefix)s %(message)s" logging.config.dictConfig(self.log_config) elif self.log_config.endswith(".json"): with open(self.log_config) as file: diff --git a/uvicorn/logging.py b/uvicorn/logging.py index f22ed8d72..60d7e982c 100644 --- a/uvicorn/logging.py +++ b/uvicorn/logging.py @@ -1,11 +1,18 @@ import http import logging import sys +import time +import typing +from collections import abc from copy import copy -from typing import Optional +from os import getpid +from typing import Any, Callable, Dict, Iterator, Optional import click +if typing.TYPE_CHECKING: + import uvicorn.protocols.utils + TRACE_LOG_LEVEL = 5 @@ -95,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, @@ -115,3 +124,194 @@ def formatMessage(self, record: logging.LogRecord) -> str: } ) return super().formatMessage(recordcopy) + + +class AccessLogFields(abc.Mapping): # pragma: no cover + """Container to provide fields for access logging. + + This class does a few things: + - 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__( + self, scope: dict, timing: "uvicorn.protocols.utils.RequestResponseTiming" + ): + self.scope = scope + self.timing = timing + self.status_code = None + self.response_headers: Dict[str, str] = {} + self._response_length = 0 + + self._request_headers: Optional[Dict[str, str]] = None + + @property + 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"] + } + return self._request_headers + + @property + def duration(self) -> float: + return self.timing.total_duration_seconds() + + 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.get("headers") or {} + } + elif message["type"] == "http.response.body": + self._response_length += len(message.get("body", "")) + + def _request_header(self, key: str) -> Optional[str]: + return self.request_headers.get(key.lower()) + + def _response_header(self, key: str) -> Optional[str]: + return self.response_headers.get(key.lower()) + + def _wsgi_environ_variable(self, key: str) -> None: + # FIXME: provide fallbacks to access WSGI environ (at least the + # required variables). + raise NotImplementedError + + @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("{"): + 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]) + raise NotImplementedError("WSGI environ not supported") + else: + retval = None + else: + retval = None + return self._log_format_atom(retval) + + _LogAtomHandler = Callable[["AccessLogFields"], Optional[str]] + HANDLERS: Dict[str, _LogAtomHandler] = {} + + # 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[["AccessLogFields"], Optional[str]] + + def decorator(fn: _LogAtomHandler) -> _LogAtomHandler: + handlers[key] = fn + return fn + + return decorator + + @_register_handler("h") + def _remote_address(self) -> Optional[str]: + return self.scope["client"][0] + + @_register_handler("l") + def _dash(self) -> str: + return "-" + + @_register_handler("u") + def _user_name(self) -> Optional[str]: + pass + + @_register_handler("t") + 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) -> 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( + full_path=full_path, **self.scope + ) + + @_register_handler("m") + def request_method(self) -> Optional[str]: + return self.scope["method"] + + @_register_handler("U") + def url_path(self) -> Optional[str]: + return self.scope["raw_path"].decode("ascii") + + @_register_handler("q") + def query_string(self) -> Optional[str]: + return self.scope["query_string"].decode("ascii") + + @_register_handler("H") + def protocol(self) -> Optional[str]: + return "HTTP/%s" % self.scope["http_version"] + + @_register_handler("s") + def status(self) -> Optional[str]: + return self.status_code or "-" + + @_register_handler("B") + def response_length(self) -> Optional[str]: + return str(self._response_length) + + @_register_handler("b") + def response_length_or_dash(self) -> Optional[str]: + return str(self._response_length or "-") + + @_register_handler("f") + def referer(self) -> Optional[str]: + return self.request_headers.get("referer") + + @_register_handler("a") + def user_agent(self) -> Optional[str]: + return self.request_headers.get("user-agent") + + @_register_handler("T") + def request_time_seconds(self) -> Optional[str]: + return str(int(self.duration)) + + @_register_handler("D") + def request_time_microseconds(self) -> str: + return str(int(self.duration * 1_000_000)) + + @_register_handler("L") + def request_time_decimal_seconds(self) -> str: + return "%.6f" % self.duration + + @_register_handler("p") + def process_id(self) -> str: + return "<%s>" % getpid() + + def __iter__(self) -> Iterator[str]: + # 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) -> int: + # FIXME: add WSGI environ + return ( + len(self.HANDLERS) + + len(self.scope["headers"] or ()) + + len(self.response_headers) + ) diff --git a/uvicorn/main.py b/uvicorn/main.py index cd853b613..492f3b0f7 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="Log format for access logger, check documentation for details", +) @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, diff --git a/uvicorn/protocols/http/h11_impl.py b/uvicorn/protocols/http/h11_impl.py index 78e5ffdc1..1061c63ba 100644 --- a/uvicorn/protocols/http/h11_impl.py +++ b/uvicorn/protocols/http/h11_impl.py @@ -1,11 +1,12 @@ import asyncio import http import logging +import traceback from urllib.parse import unquote import h11 -from uvicorn.logging import TRACE_LOG_LEVEL +from uvicorn.logging import TRACE_LOG_LEVEL, AccessLogFields from uvicorn.protocols.http.flow_control import ( CLOSE_HEADER, HIGH_WATER_LIMIT, @@ -13,6 +14,7 @@ service_unavailable, ) from uvicorn.protocols.utils import ( + RequestResponseTiming, get_client_addr, get_local_addr, get_path_with_query_string, @@ -192,10 +194,12 @@ def handle_events(self): logger=self.logger, access_logger=self.access_logger, access_log=self.access_log, + access_log_format=self.config.access_log_format, default_headers=self.default_headers, message_event=asyncio.Event(), on_response=self.on_response_complete, ) + 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) @@ -213,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() @@ -330,6 +335,7 @@ def __init__( logger, access_logger, access_log, + access_log_format, default_headers, message_event, on_response, @@ -341,6 +347,7 @@ def __init__( self.logger = logger self.access_logger = access_logger self.access_log = access_log + self.access_log_format = access_log_format self.default_headers = default_headers self.message_event = message_event self.on_response = on_response @@ -357,6 +364,10 @@ def __init__( # Response state self.response_started = False self.response_complete = False + self.timing = RequestResponseTiming() + + # For logging + self.access_log_fields = AccessLogFields(self.scope, self.timing) # ASGI exception wrapper async def run_asgi(self, app): @@ -410,6 +421,9 @@ async def send(self, message): if self.disconnected: return + 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 if message_type != "http.response.start": @@ -418,6 +432,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", []) @@ -425,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: - 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( @@ -468,6 +473,27 @@ async def send(self, message): output = self.conn.send(event) self.transport.write(output) + self.timing.response_ended() + + 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 msg = "Unexpected ASGI message '%s' sent, after response already completed." diff --git a/uvicorn/protocols/http/httptools_impl.py b/uvicorn/protocols/http/httptools_impl.py index e6183bbcb..971dbb794 100644 --- a/uvicorn/protocols/http/httptools_impl.py +++ b/uvicorn/protocols/http/httptools_impl.py @@ -2,12 +2,14 @@ import http import logging import re +import time +import traceback import urllib from collections import deque import httptools -from uvicorn.logging import TRACE_LOG_LEVEL +from uvicorn.logging import TRACE_LOG_LEVEL, AccessLogFields from uvicorn.protocols.http.flow_control import ( CLOSE_HEADER, HIGH_WATER_LIMIT, @@ -15,6 +17,7 @@ service_unavailable, ) from uvicorn.protocols.utils import ( + RequestResponseTiming, get_client_addr, get_local_addr, get_path_with_query_string, @@ -50,6 +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.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 @@ -79,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): @@ -205,6 +210,9 @@ def on_url(self, url): "headers": self.headers, } + 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": @@ -237,12 +245,14 @@ def on_headers_complete(self): logger=self.logger, access_logger=self.access_logger, access_log=self.access_log, + access_log_format=self.access_log_format, default_headers=self.default_headers, message_event=asyncio.Event(), expect_100_continue=self.expect_100_continue, 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)) @@ -266,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. @@ -330,6 +341,7 @@ def __init__( logger, access_logger, access_log, + access_log_format, default_headers, message_event, expect_100_continue, @@ -342,6 +354,7 @@ def __init__( self.logger = logger self.access_logger = access_logger self.access_log = access_log + self.access_log_format = access_log_format self.default_headers = default_headers self.message_event = message_event self.on_response = on_response @@ -360,6 +373,10 @@ def __init__( self.response_complete = False self.chunked_encoding = None self.expected_content_length = 0 + self.timing = RequestResponseTiming() + + # For logging. + self.access_log_fields = AccessLogFields(self.scope, self.timing) # ASGI exception wrapper async def run_asgi(self, app): @@ -413,6 +430,8 @@ async def send(self, message): if self.disconnected: return + self.access_log_fields.on_asgi_message(message) + if not self.response_started: # Sending response status line and headers if message_type != "http.response.start": @@ -420,6 +439,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"] @@ -428,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: - 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]] @@ -503,7 +513,29 @@ async def send(self, message): if self.expected_content_length != 0: raise RuntimeError("Response content shorter than Content-Length") self.response_complete = True + self.timing.response_ended() + 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, + ) + else: + try: + self.access_logger.info( + self.access_log_format, + self.access_log_fields, + ) + except: # noqa + self.logger.error(traceback.format_exc()) + if not self.keep_alive: self.transport.close() self.on_response() diff --git a/uvicorn/protocols/utils.py b/uvicorn/protocols/utils.py index 1da733600..072edebb0 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,61 @@ 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: + # 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 + 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) -> float: + return self.response_end_time - self.response_start_time + + def total_duration_seconds(self) -> float: + return self.response_end_time - self.request_start_time diff --git a/uvicorn/workers.py b/uvicorn/workers.py index f28c3a8d4..440436c80 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, + "access_log_format": self.log.cfg.access_log_format, } if self.cfg.is_ssl: