diff --git a/docs/deployment.md b/docs/deployment.md index ad8c099aa..376bf430b 100644 --- a/docs/deployment.md +++ b/docs/deployment.md @@ -70,6 +70,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 1b34808de..6a2a79cbe 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/requirements.txt b/requirements.txt index 9cb3205be..864352205 100644 --- a/requirements.txt +++ b/requirements.txt @@ -23,6 +23,7 @@ coverage httpx>=0.18.2 pytest-asyncio==0.14.* async_generator; python_version < '3.7' +gunicorn # Documentation diff --git a/tests/middleware/test_logging.py b/tests/middleware/test_logging.py index 8b8cbd29b..bce3bcfd2 100644 --- a/tests/middleware/test_logging.py +++ b/tests/middleware/test_logging.py @@ -1,5 +1,6 @@ import contextlib import logging +import re import httpx import pytest @@ -9,6 +10,11 @@ from uvicorn import Config +def escape_ansi(line: str): + ansi_escape = re.compile(r"(?:\x1B[@-_]|[\x80-\x9F])[0-?]*[ -/]*[@-~]") + return ansi_escape.sub("", line) + + @contextlib.contextmanager def caplog_for_logger(caplog, logger_name): logger = logging.getLogger(logger_name) @@ -110,7 +116,7 @@ async def test_access_logging(use_colors, caplog): for record in caplog.records if record.name == "uvicorn.access" ] - assert '"GET / HTTP/1.1" 204' in messages.pop() + assert '"GET / HTTP/1.1" 204' in escape_ansi(messages.pop()) @pytest.mark.asyncio @@ -130,7 +136,7 @@ async def test_default_logging(use_colors, caplog): assert "ASGI 'lifespan' protocol appears unsupported" in messages.pop(0) assert "Application startup complete" in messages.pop(0) assert "Uvicorn running on http://127.0.0.1:8000" in messages.pop(0) - assert '"GET / HTTP/1.1" 204' in messages.pop(0) + assert '"GET / HTTP/1.1" 204' in escape_ansi(messages.pop(0)) assert "Shutting down" in messages.pop(0) diff --git a/uvicorn/config.py b/uvicorn/config.py index 13f58988e..1ecdefc8e 100644 --- a/uvicorn/config.py +++ b/uvicorn/config.py @@ -202,6 +202,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, @@ -274,6 +275,11 @@ def __init__( self.encoded_headers: List[Tuple[bytes, bytes]] = [] self.factory = factory + if access_log_format is None: + self.access_log_format = '%(h)s - "%(request_line)s" %(status_code)s' + else: + self.access_log_format = access_log_format + self.loaded = False self.configure_logging() @@ -375,6 +381,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..1fbb8dcd0 100644 --- a/uvicorn/logging.py +++ b/uvicorn/logging.py @@ -1,10 +1,15 @@ import http import logging +import os import sys +import time from copy import copy from typing import Optional import click +from asgiref.typing import HTTPResponseStartEvent, HTTPScope + +from uvicorn.protocols.utils import get_client_addr, get_path_with_query_string TRACE_LOG_LEVEL = 5 @@ -96,22 +101,76 @@ def default(code: int) -> str: def formatMessage(self, record: logging.LogRecord) -> str: recordcopy = copy(record) - ( - client_addr, - method, - full_path, - http_version, - status_code, - ) = recordcopy.args + request_line = recordcopy.args["request_line"] # type: ignore[call-overload] + status_code = recordcopy.args["s"] # type: ignore[call-overload] + status_code = self.get_status_code(int(status_code)) - request_line = "%s %s HTTP/%s" % (method, full_path, http_version) if self.use_colors: request_line = click.style(request_line, bold=True) - recordcopy.__dict__.update( + recordcopy.args["request_line"] = request_line # type: ignore[index] + recordcopy.args["status_code"] = status_code # type: ignore[index] + return super().formatMessage(recordcopy) + + +class AccessLogFields(dict): + def __init__( + self, + scope: HTTPScope, + response: HTTPResponseStartEvent, + request_time: float, + ) -> None: + for name, value in scope["headers"]: + self[f"{{{name.decode('latin1').lower()}}}i"] = value.decode("latin1") + for name, value in response.get("headers", []): + self[f"{{{name.decode('latin1').lower()}}}o"] = value.decode("latin1") + for name, value in os.environ.items(): # type: ignore[assignment] + self[f"{{{name.lower()!r}}}e"] = value + protocol = f"HTTP/{scope['http_version']}" + path = scope["root_path"] + scope["path"] + full_path = get_path_with_query_string(scope) + request_line = f"{scope['method']} {path} {protocol}" + full_request_line = f"{scope['method']} {full_path} {protocol}" + client_addr = get_client_addr(scope) or "-" + + try: + status_phrase = http.HTTPStatus(response["status"]).phrase + except ValueError: + status_phrase = "-" + + self.update( { + "h": client_addr, "client_addr": client_addr, - "request_line": request_line, - "status_code": status_code, + "l": "-", + "u": "-", # Not available on ASGI. + "t": time.strftime("[%d/%b/%Y:%H:%M:%S %z]"), + "r": request_line, + "request_line": full_request_line, + "R": full_request_line, + "m": scope["method"], + "U": scope["path"], + "q": scope["query_string"].decode(), + "H": protocol, + "s": response["status"], + "st": status_phrase, + "status_code": f"{response['status']} {status_phrase}", + "B": self["{Content-Length}o"], + "b": self.get("{Content-Length}o", "-"), + "f": self["{Referer}i"], + "a": self["{User-Agent}i"], + "T": int(request_time), + "M": int(request_time * 1_000), + "D": int(request_time * 1_000_000), + "L": f"{request_time:.6f}", + "p": f"<{os.getpid()}>", } ) - return super().formatMessage(recordcopy) + + def __getitem__(self, key: str) -> str: + try: + if key.startswith("{"): + return super().__getitem__(key.lower()) + else: + return super().__getitem__(key) + except KeyError: + return "-" diff --git a/uvicorn/main.py b/uvicorn/main.py index 9d48c562e..e26cf4edd 100644 --- a/uvicorn/main.py +++ b/uvicorn/main.py @@ -192,6 +192,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, @@ -355,6 +361,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, @@ -394,6 +401,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 04b997ffe..3341a55cf 100644 --- a/uvicorn/protocols/http/h11_impl.py +++ b/uvicorn/protocols/http/h11_impl.py @@ -1,25 +1,22 @@ import asyncio import http import logging +import traceback +from time import time from typing import Callable from urllib.parse import unquote import h11 +from asgiref.typing import HTTPResponseStartEvent -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, FlowControl, service_unavailable, ) -from uvicorn.protocols.utils import ( - get_client_addr, - get_local_addr, - get_path_with_query_string, - get_remote_addr, - is_ssl, -) +from uvicorn.protocols.utils import get_local_addr, get_remote_addr, is_ssl def _get_status_phrase(status_code): @@ -199,6 +196,7 @@ 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, @@ -339,6 +337,7 @@ def __init__( logger, access_logger, access_log, + access_log_format, default_headers, message_event, on_response, @@ -350,6 +349,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 @@ -366,6 +366,8 @@ def __init__( # Response state self.response_started = False self.response_complete = False + self.start_time = time() + self.response: HTTPResponseStartEvent # ASGI exception wrapper async def run_asgi(self, app): @@ -425,6 +427,7 @@ async def send(self, message): msg = "Expected ASGI message 'http.response.start', but got '%s'." raise RuntimeError(msg % message_type) + self.response = message self.response_started = True self.waiting_for_100_continue = False @@ -434,16 +437,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( @@ -477,6 +470,17 @@ async def send(self, message): output = self.conn.send(event) self.transport.write(output) + if self.access_log: + try: + self.access_logger.info( + self.access_log_format, + AccessLogFields( + self.scope, self.response, time() - self.start_time + ), + ) + 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 557bd4f2a..8f261f9f6 100644 --- a/uvicorn/protocols/http/httptools_impl.py +++ b/uvicorn/protocols/http/httptools_impl.py @@ -2,25 +2,22 @@ import http import logging import re +import traceback import urllib +from time import time from typing import Callable import httptools +from asgiref.typing import HTTPResponseStartEvent -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, FlowControl, service_unavailable, ) -from uvicorn.protocols.utils import ( - get_client_addr, - get_local_addr, - get_path_with_query_string, - get_remote_addr, - is_ssl, -) +from uvicorn.protocols.utils import get_local_addr, get_remote_addr, is_ssl HEADER_RE = re.compile(b'[\x00-\x1F\x7F()<>@,;:[]={} \t\\"]') HEADER_VALUE_RE = re.compile(b"[\x00-\x1F\x7F]") @@ -53,6 +50,7 @@ def __init__( 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 @@ -82,6 +80,7 @@ def __init__( self.headers = None self.expect_100_continue = False self.cycle = None + self.request_start_time = None # Protocol interface def connection_made(self, transport): @@ -245,6 +244,7 @@ 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, @@ -338,6 +338,7 @@ def __init__( logger, access_logger, access_log, + access_log_format, default_headers, message_event, expect_100_continue, @@ -350,6 +351,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 @@ -368,6 +370,8 @@ def __init__( self.response_complete = False self.chunked_encoding = None self.expected_content_length = 0 + self.start_time = time() + self.response: HTTPResponseStartEvent # ASGI exception wrapper async def run_asgi(self, app): @@ -427,6 +431,7 @@ async def send(self, message): msg = "Expected ASGI message 'http.response.start', but got '%s'." raise RuntimeError(msg % message_type) + self.response = message self.response_started = True self.waiting_for_100_continue = False @@ -436,16 +441,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]] @@ -511,7 +506,20 @@ async def send(self, message): if self.expected_content_length != 0: raise RuntimeError("Response content shorter than Content-Length") self.response_complete = True + self.message_event.set() + + if self.access_log: + try: + self.access_logger.info( + self.access_log_format, + AccessLogFields( + self.scope, self.response, time() - self.start_time + ), + ) + except: # noqa + self.logger.error(traceback.format_exc()) + if not self.keep_alive: self.transport.close() self.on_response() diff --git a/uvicorn/workers.py b/uvicorn/workers.py index 05ee166af..ef12f654a 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: