From 66bf98298939eceae51a08efbecfcaf02b6a2ee9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rapha=C3=ABl=20Moreau?= Date: Tue, 5 Nov 2024 13:13:31 +0100 Subject: [PATCH] restart branch from zero --- tests/middleware/test_logging.py | 148 ++++++++++++++---- tests/middleware/test_message_logger.py | 6 +- uvicorn/__init__.py | 2 +- uvicorn/config.py | 105 ++++++++++--- uvicorn/lifespan/on.py | 3 +- uvicorn/loops/asyncio.py | 3 - uvicorn/main.py | 10 +- uvicorn/middleware/message_logger.py | 4 +- uvicorn/protocols/http/h11_impl.py | 4 +- uvicorn/protocols/http/httptools_impl.py | 4 +- .../protocols/websockets/websockets_impl.py | 2 +- uvicorn/protocols/websockets/wsproto_impl.py | 3 +- uvicorn/server.py | 30 ++-- uvicorn/supervisors/basereload.py | 9 +- uvicorn/supervisors/multiprocess.py | 34 ++-- uvicorn/supervisors/statreload.py | 7 +- uvicorn/supervisors/watchgodreload.py | 8 +- uvicorn/workers.py | 21 ++- 18 files changed, 271 insertions(+), 132 deletions(-) diff --git a/tests/middleware/test_logging.py b/tests/middleware/test_logging.py index f27633aa5..a390d7f29 100644 --- a/tests/middleware/test_logging.py +++ b/tests/middleware/test_logging.py @@ -29,6 +29,11 @@ WSProtocol: TypeAlias = "type[WebSocketProtocol | _WSProtocol]" pytestmark = pytest.mark.anyio +my_logger_mappings = { + "general": "mylogger.general", + "access": "mylogger.access", + "asgi": "mylogger.asgi", +} @contextlib.contextmanager @@ -49,20 +54,23 @@ async def app(scope: Scope, receive: ASGIReceiveCallable, send: ASGISendCallable await send({"type": "http.response.body", "body": b"", "more_body": False}) -async def test_trace_logging(caplog: pytest.LogCaptureFixture, logging_config, unused_tcp_port: int): +@pytest.mark.parametrize("logger_mappings", [None, my_logger_mappings]) +async def test_trace_logging(caplog: pytest.LogCaptureFixture, logging_config, unused_tcp_port: int, logger_mappings): config = Config( app=app, log_level="trace", log_config=logging_config, + logger_mappings=logger_mappings, lifespan="auto", port=unused_tcp_port, ) - with caplog_for_logger(caplog, "uvicorn.asgi"): + logger_name = config.get_logger_name("asgi") + with caplog_for_logger(caplog, logger_name): async with run_server(config): async with httpx.AsyncClient() as client: response = await client.get(f"http://127.0.0.1:{unused_tcp_port}") assert response.status_code == 204 - messages = [record.message for record in caplog.records if record.name == "uvicorn.asgi"] + messages = [record.message for record in caplog.records if record.name == logger_name] assert "ASGI [1] Started scope=" in messages.pop(0) assert "ASGI [1] Raised exception" in messages.pop(0) assert "ASGI [2] Started scope=" in messages.pop(0) @@ -71,29 +79,40 @@ async def test_trace_logging(caplog: pytest.LogCaptureFixture, logging_config, u assert "ASGI [2] Completed" in messages.pop(0) -async def test_trace_logging_on_http_protocol(http_protocol_cls, caplog, logging_config, unused_tcp_port: int): +@pytest.mark.parametrize("logger_mappings", [None, my_logger_mappings]) +async def test_trace_logging_on_http_protocol( + http_protocol_cls, + caplog, + logging_config, + unused_tcp_port: int, + logger_mappings, +): config = Config( app=app, log_level="trace", http=http_protocol_cls, log_config=logging_config, + logger_mappings=logger_mappings, port=unused_tcp_port, ) - with caplog_for_logger(caplog, "uvicorn.error"): + logger_name = config.get_logger_name("general") + with caplog_for_logger(caplog, logger_name): async with run_server(config): async with httpx.AsyncClient() as client: response = await client.get(f"http://127.0.0.1:{unused_tcp_port}") assert response.status_code == 204 - messages = [record.message for record in caplog.records if record.name == "uvicorn.error"] + messages = [record.message for record in caplog.records if record.name == logger_name] assert any(" - HTTP connection made" in message for message in messages) assert any(" - HTTP connection lost" in message for message in messages) +@pytest.mark.parametrize("logger_mappings", [None, my_logger_mappings]) async def test_trace_logging_on_ws_protocol( ws_protocol_cls: WSProtocol, caplog, logging_config, unused_tcp_port: int, + logger_mappings, ): async def websocket_app(scope: Scope, receive: ASGIReceiveCallable, send: ASGISendCallable): assert scope["type"] == "websocket" @@ -112,43 +131,72 @@ async def open_connection(url): app=websocket_app, log_level="trace", log_config=logging_config, + logger_mappings=logger_mappings, ws=ws_protocol_cls, port=unused_tcp_port, ) - with caplog_for_logger(caplog, "uvicorn.error"): + logger_name = config.get_logger_name("general") + with caplog_for_logger(caplog, logger_name): async with run_server(config): is_open = await open_connection(f"ws://127.0.0.1:{unused_tcp_port}") assert is_open - messages = [record.message for record in caplog.records if record.name == "uvicorn.error"] + messages = [record.message for record in caplog.records if record.name == logger_name] assert any(" - Upgrading to WebSocket" in message for message in messages) assert any(" - WebSocket connection made" in message for message in messages) assert any(" - WebSocket connection lost" in message for message in messages) +@pytest.mark.parametrize("logger_mappings", [None, my_logger_mappings]) @pytest.mark.parametrize("use_colors", [(True), (False), (None)]) -async def test_access_logging(use_colors: bool, caplog: pytest.LogCaptureFixture, logging_config, unused_tcp_port: int): - config = Config(app=app, use_colors=use_colors, log_config=logging_config, port=unused_tcp_port) - with caplog_for_logger(caplog, "uvicorn.access"): +async def test_access_logging( + use_colors: bool, + caplog: pytest.LogCaptureFixture, + logging_config, + unused_tcp_port: int, + logger_mappings, +): + config = Config( + app=app, + use_colors=use_colors, + log_config=logging_config, + logger_mappings=logger_mappings, + port=unused_tcp_port, + ) + logger_name = config.get_logger_name("access") + with caplog_for_logger(caplog, logger_name): async with run_server(config): async with httpx.AsyncClient() as client: response = await client.get(f"http://127.0.0.1:{unused_tcp_port}") assert response.status_code == 204 - messages = [record.message for record in caplog.records if record.name == "uvicorn.access"] + messages = [record.message for record in caplog.records if record.name == logger_name] assert '"GET / HTTP/1.1" 204' in messages.pop() +@pytest.mark.parametrize("logger_mappings", [None, my_logger_mappings]) @pytest.mark.parametrize("use_colors", [(True), (False)]) async def test_default_logging( - use_colors: bool, caplog: pytest.LogCaptureFixture, logging_config, unused_tcp_port: int + use_colors: bool, + caplog: pytest.LogCaptureFixture, + logging_config, + unused_tcp_port: int, + logger_mappings, ): - config = Config(app=app, use_colors=use_colors, log_config=logging_config, port=unused_tcp_port) - with caplog_for_logger(caplog, "uvicorn.access"): + config = Config( + app=app, + use_colors=use_colors, + log_config=logging_config, + logger_mappings=logger_mappings, + port=unused_tcp_port, + ) + main_logger_name = config.get_logger_name("main") + logger_name = config.get_logger_name("access") + with caplog_for_logger(caplog, logger_name): async with run_server(config): async with httpx.AsyncClient() as client: response = await client.get(f"http://127.0.0.1:{unused_tcp_port}") assert response.status_code == 204 - messages = [record.message for record in caplog.records if "uvicorn" in record.name] + messages = [record.message for record in caplog.records if main_logger_name in record.name] assert "Started server process" in messages.pop(0) assert "Waiting for application startup" in messages.pop(0) assert "ASGI 'lifespan' protocol appears unsupported" in messages.pop(0) @@ -159,53 +207,91 @@ async def test_default_logging( @pytest.mark.skipif(sys.platform == "win32", reason="require unix-like system") +@pytest.mark.parametrize("logger_mappings", [None, my_logger_mappings]) async def test_running_log_using_uds( - caplog: pytest.LogCaptureFixture, short_socket_name: str, unused_tcp_port: int + caplog: pytest.LogCaptureFixture, + short_socket_name: str, + unused_tcp_port: int, + logger_mappings, ): # pragma: py-win32 - config = Config(app=app, uds=short_socket_name, port=unused_tcp_port) - with caplog_for_logger(caplog, "uvicorn.access"): + config = Config( + app=app, + uds=short_socket_name, + port=unused_tcp_port, + logger_mappings=logger_mappings, + ) + with caplog_for_logger(caplog, config.get_logger_name("access")): async with run_server(config): ... - messages = [record.message for record in caplog.records if "uvicorn" in record.name] + messages = [record.message for record in caplog.records if config.get_logger_name("main") in record.name] assert f"Uvicorn running on unix socket {short_socket_name} (Press CTRL+C to quit)" in messages @pytest.mark.skipif(sys.platform == "win32", reason="require unix-like system") -async def test_running_log_using_fd(caplog: pytest.LogCaptureFixture, unused_tcp_port: int): # pragma: py-win32 +@pytest.mark.parametrize("logger_mappings", [None, my_logger_mappings]) +async def test_running_log_using_fd( + caplog: pytest.LogCaptureFixture, + unused_tcp_port: int, + logger_mappings, +): # pragma: py-win32 with contextlib.closing(socket.socket(socket.AF_INET, socket.SOCK_STREAM)) as sock: fd = sock.fileno() - config = Config(app=app, fd=fd, port=unused_tcp_port) - with caplog_for_logger(caplog, "uvicorn.access"): + config = Config( + app=app, + fd=fd, + port=unused_tcp_port, + logger_mappings=logger_mappings, + ) + with caplog_for_logger(caplog, config.get_logger_name("access")): async with run_server(config): ... sockname = sock.getsockname() - messages = [record.message for record in caplog.records if "uvicorn" in record.name] + messages = [record.message for record in caplog.records if config.get_logger_name("main") in record.name] assert f"Uvicorn running on socket {sockname} (Press CTRL+C to quit)" in messages -async def test_unknown_status_code(caplog: pytest.LogCaptureFixture, unused_tcp_port: int): +@pytest.mark.parametrize("logger_mappings", [None, my_logger_mappings]) +async def test_unknown_status_code( + caplog: pytest.LogCaptureFixture, + unused_tcp_port: int, + logger_mappings, +): async def app(scope: Scope, receive: ASGIReceiveCallable, send: ASGISendCallable): assert scope["type"] == "http" await send({"type": "http.response.start", "status": 599, "headers": []}) await send({"type": "http.response.body", "body": b"", "more_body": False}) - config = Config(app=app, port=unused_tcp_port) - with caplog_for_logger(caplog, "uvicorn.access"): + config = Config( + app=app, + port=unused_tcp_port, + logger_mappings=logger_mappings, + ) + logger_name = config.get_logger_name("access") + with caplog_for_logger(caplog, logger_name): async with run_server(config): async with httpx.AsyncClient() as client: response = await client.get(f"http://127.0.0.1:{unused_tcp_port}") assert response.status_code == 599 - messages = [record.message for record in caplog.records if record.name == "uvicorn.access"] + messages = [record.message for record in caplog.records if record.name == logger_name] assert '"GET / HTTP/1.1" 599' in messages.pop() -async def test_server_start_with_port_zero(caplog: pytest.LogCaptureFixture): - config = Config(app=app, port=0) +@pytest.mark.parametrize("logger_mappings", [None, my_logger_mappings]) +async def test_server_start_with_port_zero( + caplog: pytest.LogCaptureFixture, + logger_mappings, +): + config = Config( + app=app, + port=0, + logger_mappings=logger_mappings, + ) + logger_name = config.get_logger_name("main") async with run_server(config) as _server: server = _server.servers[0] sock = server.sockets[0] host, port = sock.getsockname() - messages = [record.message for record in caplog.records if "uvicorn" in record.name] + messages = [record.message for record in caplog.records if logger_name in record.name] assert f"Uvicorn running on http://{host}:{port} (Press CTRL+C to quit)" in messages diff --git a/tests/middleware/test_message_logger.py b/tests/middleware/test_message_logger.py index db307b326..3f963fef5 100644 --- a/tests/middleware/test_message_logger.py +++ b/tests/middleware/test_message_logger.py @@ -1,3 +1,5 @@ +import logging + import httpx import pytest @@ -17,7 +19,7 @@ async def app(scope, receive, send): caplog.set_level(TRACE_LOG_LEVEL, logger="uvicorn.asgi") caplog.set_level(TRACE_LOG_LEVEL) - transport = httpx.ASGITransport(MessageLoggerMiddleware(app)) # type: ignore + transport = httpx.ASGITransport(MessageLoggerMiddleware(app, logging.getLogger("uvicorn.asgi"))) # type: ignore async with httpx.AsyncClient(transport=transport, base_url="http://testserver") as client: response = await client.get("/") assert response.status_code == 200 @@ -37,7 +39,7 @@ async def app(scope, receive, send): with caplog_for_logger(caplog, "uvicorn.asgi"): caplog.set_level(TRACE_LOG_LEVEL, logger="uvicorn.asgi") caplog.set_level(TRACE_LOG_LEVEL) - transport = httpx.ASGITransport(MessageLoggerMiddleware(app)) # type: ignore + transport = httpx.ASGITransport(MessageLoggerMiddleware(app, logging.getLogger("uvicorn.asgi"))) # type: ignore async with httpx.AsyncClient(transport=transport, base_url="http://testserver") as client: with pytest.raises(RuntimeError): await client.get("/") diff --git a/uvicorn/__init__.py b/uvicorn/__init__.py index c5c7b8f33..fb1c30ca5 100644 --- a/uvicorn/__init__.py +++ b/uvicorn/__init__.py @@ -1,5 +1,5 @@ from uvicorn.config import Config from uvicorn.main import Server, main, run -__version__ = "0.32.0" +__version__ = "0.32.0+logger_names_patched" __all__ = ["main", "run", "Config", "Server"] diff --git a/uvicorn/config.py b/uvicorn/config.py index 65dfe651e..29a9b2094 100644 --- a/uvicorn/config.py +++ b/uvicorn/config.py @@ -10,6 +10,7 @@ import ssl import sys from configparser import RawConfigParser +from copy import deepcopy from pathlib import Path from typing import IO, Any, Awaitable, Callable, Literal @@ -96,8 +97,6 @@ }, } -logger = logging.getLogger("uvicorn.error") - def create_ssl_context( certfile: str | os.PathLike[str], @@ -194,6 +193,7 @@ def __init__( log_level: str | int | None = None, access_log: bool = True, use_colors: bool | None = None, + logger_mappings: dict | None = None, interface: InterfaceType = "auto", reload: bool = False, reload_dirs: list[str] | str | None = None, @@ -270,6 +270,7 @@ def __init__( self.h11_max_incomplete_event_size = h11_max_incomplete_event_size self.loaded = False + self.logger_mappings = logger_mappings if logger_mappings else {} self.configure_logging() self.reload_dirs: list[Path] = [] @@ -278,7 +279,7 @@ def __init__( self.reload_excludes: list[str] = [] if (reload_dirs or reload_includes or reload_excludes) and not self.should_reload: - logger.warning( + self.get_logger("general").warning( "Current configuration will not reload as not all conditions are met, " "please refer to documentation." ) @@ -307,14 +308,14 @@ def __init__( if not self.reload_dirs: if reload_dirs: - logger.warning( + self.get_logger("general").warning( "Provided reload directories %s did not contain valid " + "directories, watching current working directory.", reload_dirs, ) self.reload_dirs = [Path(os.getcwd())] - logger.info( + self.get_logger("general").info( "Will watch for changes in these directories: %s", sorted(list(map(str, self.reload_dirs))), ) @@ -322,7 +323,7 @@ def __init__( if env_file is not None: from dotenv import load_dotenv - logger.info("Loading environment from '%s'", env_file) + self.get_logger("general").info("Loading environment from '%s'", env_file) load_dotenv(dotenv_path=env_file) if workers is None and "WEB_CONCURRENCY" in os.environ: @@ -335,7 +336,7 @@ def __init__( self.forwarded_allow_ips = forwarded_allow_ips # pragma: full coverage if self.reload and self.workers > 1: - logger.warning('"workers" flag is ignored when reloading is enabled.') + self.get_logger("general").warning('"workers" flag is ignored when reloading is enabled.') @property def asgi_version(self) -> Literal["2.0", "3.0"]: @@ -354,19 +355,76 @@ def is_ssl(self) -> bool: def use_subprocess(self) -> bool: return bool(self.reload or self.workers > 1) + def get_logger_name(self, sub_logger: str) -> str: + return self._internal_logger_mappings[sub_logger] + + def get_logger(self, sub_logger: str) -> logging.Logger: + return logging.getLogger(self.get_logger_name(sub_logger)) + + def do_dict_config(self, log_config: dict) -> None: + # # rewrite the log config to use correct logger names + if "loggers" in log_config: + # do a deep copy to keep original values + cpy = deepcopy(log_config) + # very dirty hack to keep maximum compatibility + loggers = {} + log_map = { + "uvicorn": "main", + "uvicorn.error": "general", + "uvicorn.access": "access", + "uvicorn.asgi": "asgi", + } + for k, v in cpy["loggers"].items(): + loggers[self.get_logger_name(log_map[k]) if k in log_map else k] = v + cpy["loggers"] = loggers + log_config = cpy + # # apply log configuration + logging.config.dictConfig(log_config) + + @staticmethod + def get_longest_common_prefix(strs: list) -> str: + if not strs: # pragma: no cover + return "" + strs = sorted(strs) + min_s = min(strs) + max_s = max(strs) + if not min_s: # pragma: no cover + return "" + for i in range(len(min_s)): + if max_s[i] != min_s[i]: + return max_s[:i] + return min_s[:] # pragma: no cover + def configure_logging(self) -> None: logging.addLevelName(TRACE_LOG_LEVEL, "TRACE") + self._internal_logger_mappings = { + "general": self.logger_mappings.get("general", "uvicorn.error"), + "access": self.logger_mappings.get("access", "uvicorn.access"), + "asgi": self.logger_mappings.get("asgi", "uvicorn.asgi"), + } + # get longest prefix in loggers to configure the main + common = Config.get_longest_common_prefix(list(self._internal_logger_mappings.values())) + if not common.endswith("."): # pragma: no cover + check = f"{common}." + for s in self._internal_logger_mappings.values(): + if s != common and not s.startswith(check): + raise Exception("failed to find a common ancestor for logger mappings") + # need to add the dot at the end for next line + common = check + + self._internal_logger_mappings["main"] = common[:-1] + if self.log_config is not None: if isinstance(self.log_config, dict): if self.use_colors in (True, False): self.log_config["formatters"]["default"]["use_colors"] = self.use_colors self.log_config["formatters"]["access"]["use_colors"] = self.use_colors - logging.config.dictConfig(self.log_config) + self.do_dict_config(self.log_config) elif isinstance(self.log_config, str) and self.log_config.endswith(".json"): with open(self.log_config) as file: loaded_config = json.load(file) - logging.config.dictConfig(loaded_config) + self.do_dict_config(loaded_config) elif isinstance(self.log_config, str) and self.log_config.endswith((".yaml", ".yml")): # Install the PyYAML package or the uvicorn[standard] optional # dependencies to enable this functionality. @@ -374,7 +432,7 @@ def configure_logging(self) -> None: with open(self.log_config) as file: loaded_config = yaml.safe_load(file) - logging.config.dictConfig(loaded_config) + self.do_dict_config(loaded_config) else: # See the note about fileConfig() here: # https://docs.python.org/3/library/logging.config.html#configuration-file-format @@ -385,12 +443,12 @@ def configure_logging(self) -> None: log_level = LOG_LEVELS[self.log_level] else: log_level = self.log_level - logging.getLogger("uvicorn.error").setLevel(log_level) - logging.getLogger("uvicorn.access").setLevel(log_level) - logging.getLogger("uvicorn.asgi").setLevel(log_level) + self.get_logger("general").setLevel(log_level) + self.get_logger("access").setLevel(log_level) + self.get_logger("asgi").setLevel(log_level) if self.access_log is False: - logging.getLogger("uvicorn.access").handlers = [] - logging.getLogger("uvicorn.access").propagate = False + self.get_logger("access").handlers = [] + self.get_logger("access").propagate = False def load(self) -> None: assert not self.loaded @@ -433,18 +491,18 @@ def load(self) -> None: try: self.loaded_app = import_from_string(self.app) except ImportFromStringError as exc: - logger.error("Error loading ASGI app. %s" % exc) + self.get_logger("general").error("Error loading ASGI app. %s" % exc) sys.exit(1) try: self.loaded_app = self.loaded_app() except TypeError as exc: if self.factory: - logger.error("Error loading ASGI app factory: %s", exc) + self.get_logger("general").error("Error loading ASGI app factory: %s", exc) sys.exit(1) else: if not self.factory: - logger.warning( + self.get_logger("general").warning( "ASGI app factory detected. Using it, " "but please consider setting the --factory flag explicitly." ) @@ -464,8 +522,9 @@ def load(self) -> None: elif self.interface == "asgi2": self.loaded_app = ASGI2Middleware(self.loaded_app) - if logger.getEffectiveLevel() <= TRACE_LOG_LEVEL: - self.loaded_app = MessageLoggerMiddleware(self.loaded_app) + if self.get_logger("general").getEffectiveLevel() <= TRACE_LOG_LEVEL: + # self.loaded_app = MessageLoggerMiddleware(self.loaded_app) + self.loaded_app = MessageLoggerMiddleware(self.loaded_app, self.get_logger("asgi")) if self.proxy_headers: self.loaded_app = ProxyHeadersMiddleware(self.loaded_app, trusted_hosts=self.forwarded_allow_ips) @@ -486,7 +545,7 @@ def bind_socket(self) -> socket.socket: uds_perms = 0o666 os.chmod(self.uds, uds_perms) except OSError as exc: # pragma: full coverage - logger.error(exc) + self.get_logger("general").error(exc) sys.exit(1) message = "Uvicorn running on unix socket %s (Press CTRL+C to quit)" @@ -513,14 +572,14 @@ def bind_socket(self) -> socket.socket: try: sock.bind((self.host, self.port)) except OSError as exc: # pragma: full coverage - logger.error(exc) + self.get_logger("general").error(exc) sys.exit(1) message = f"Uvicorn running on {addr_format} (Press CTRL+C to quit)" color_message = "Uvicorn running on " + click.style(addr_format, bold=True) + " (Press CTRL+C to quit)" protocol_name = "https" if self.is_ssl else "http" logger_args = [protocol_name, self.host, sock.getsockname()[1]] - logger.info(message, *logger_args, extra={"color_message": color_message}) + self.get_logger("general").info(message, *logger_args, extra={"color_message": color_message}) sock.set_inheritable(True) return sock diff --git a/uvicorn/lifespan/on.py b/uvicorn/lifespan/on.py index 09df984ea..59b1cc01f 100644 --- a/uvicorn/lifespan/on.py +++ b/uvicorn/lifespan/on.py @@ -1,7 +1,6 @@ from __future__ import annotations import asyncio -import logging from asyncio import Queue from typing import Any, Union @@ -34,7 +33,7 @@ def __init__(self, config: Config) -> None: config.load() self.config = config - self.logger = logging.getLogger("uvicorn.error") + self.logger = config.get_logger("general") self.startup_event = asyncio.Event() self.shutdown_event = asyncio.Event() self.receive_queue: Queue[LifespanReceiveMessage] = asyncio.Queue() diff --git a/uvicorn/loops/asyncio.py b/uvicorn/loops/asyncio.py index 1bead4a06..3b1b650b1 100644 --- a/uvicorn/loops/asyncio.py +++ b/uvicorn/loops/asyncio.py @@ -1,9 +1,6 @@ import asyncio -import logging import sys -logger = logging.getLogger("uvicorn.error") - def asyncio_setup(use_subprocess: bool = False) -> None: if sys.platform == "win32" and use_subprocess: diff --git a/uvicorn/main.py b/uvicorn/main.py index 96a10d538..5b8a299cc 100644 --- a/uvicorn/main.py +++ b/uvicorn/main.py @@ -1,7 +1,6 @@ from __future__ import annotations import asyncio -import logging import os import platform import ssl @@ -41,8 +40,6 @@ STARTUP_FAILURE = 3 -logger = logging.getLogger("uvicorn.error") - def print_version(ctx: click.Context, param: click.Parameter, value: bool) -> None: if not value or ctx.resilient_parsing: @@ -486,6 +483,7 @@ def run( env_file: str | os.PathLike[str] | None = None, log_config: dict[str, Any] | str | RawConfigParser | IO[Any] | None = LOGGING_CONFIG, log_level: str | int | None = None, + logger_mappings: dict | None = None, access_log: bool = True, proxy_headers: bool = True, server_header: bool = True, @@ -539,6 +537,7 @@ def run( log_config=log_config, log_level=log_level, access_log=access_log, + logger_mappings=logger_mappings, proxy_headers=proxy_headers, server_header=server_header, date_header=date_header, @@ -564,8 +563,9 @@ def run( server = Server(config=config) if (config.reload or config.workers > 1) and not isinstance(app, str): - logger = logging.getLogger("uvicorn.error") - logger.warning("You must pass the application as an import string to enable 'reload' or " "'workers'.") + config.get_logger("general").warning( + "You must pass the application as an import string to enable 'reload' or " "'workers'." + ) sys.exit(1) try: diff --git a/uvicorn/middleware/message_logger.py b/uvicorn/middleware/message_logger.py index 0174bcce6..e92bee44d 100644 --- a/uvicorn/middleware/message_logger.py +++ b/uvicorn/middleware/message_logger.py @@ -34,10 +34,10 @@ def message_with_placeholders(message: Any) -> Any: class MessageLoggerMiddleware: - def __init__(self, app: "ASGI3Application"): + def __init__(self, app: "ASGI3Application", logger: logging.Logger): self.task_counter = 0 self.app = app - self.logger = logging.getLogger("uvicorn.asgi") + self.logger = logger def trace(message: Any, *args: Any, **kwargs: Any) -> None: self.logger.log(TRACE_LOG_LEVEL, message, *args, **kwargs) diff --git a/uvicorn/protocols/http/h11_impl.py b/uvicorn/protocols/http/h11_impl.py index 932ddf62b..a872eb8ac 100644 --- a/uvicorn/protocols/http/h11_impl.py +++ b/uvicorn/protocols/http/h11_impl.py @@ -49,8 +49,8 @@ def __init__( self.config = config self.app = config.loaded_app self.loop = _loop or asyncio.get_event_loop() - self.logger = logging.getLogger("uvicorn.error") - self.access_logger = logging.getLogger("uvicorn.access") + self.logger = config.get_logger("general") + self.access_logger = config.get_logger("access") self.access_log = self.access_logger.hasHandlers() self.conn = h11.Connection( h11.SERVER, diff --git a/uvicorn/protocols/http/httptools_impl.py b/uvicorn/protocols/http/httptools_impl.py index 00f1fb720..f52bc650a 100644 --- a/uvicorn/protocols/http/httptools_impl.py +++ b/uvicorn/protocols/http/httptools_impl.py @@ -54,8 +54,8 @@ def __init__( self.config = config self.app = config.loaded_app self.loop = _loop or asyncio.get_event_loop() - self.logger = logging.getLogger("uvicorn.error") - self.access_logger = logging.getLogger("uvicorn.access") + self.logger = config.get_logger("general") + self.access_logger = config.get_logger("access") self.access_log = self.access_logger.hasHandlers() self.parser = httptools.HttpRequestParser(self) self.ws_protocol_class = config.ws_protocol_class diff --git a/uvicorn/protocols/websockets/websockets_impl.py b/uvicorn/protocols/websockets/websockets_impl.py index af66c29b3..63162e23c 100644 --- a/uvicorn/protocols/websockets/websockets_impl.py +++ b/uvicorn/protocols/websockets/websockets_impl.py @@ -108,7 +108,7 @@ def __init__( ping_interval=self.config.ws_ping_interval, ping_timeout=self.config.ws_ping_timeout, extensions=extensions, - logger=logging.getLogger("uvicorn.error"), + logger=self.config.get_logger("general"), ) self.server_header = None self.extra_headers = [ diff --git a/uvicorn/protocols/websockets/wsproto_impl.py b/uvicorn/protocols/websockets/wsproto_impl.py index 072dec942..80ffa3665 100644 --- a/uvicorn/protocols/websockets/wsproto_impl.py +++ b/uvicorn/protocols/websockets/wsproto_impl.py @@ -1,7 +1,6 @@ from __future__ import annotations import asyncio -import logging import typing from typing import Literal, cast from urllib.parse import unquote @@ -49,7 +48,7 @@ def __init__( self.config = config self.app = cast(ASGI3Application, config.loaded_app) self.loop = _loop or asyncio.get_event_loop() - self.logger = logging.getLogger("uvicorn.error") + self.logger = config.get_logger("general") self.root_path = config.root_path self.app_state = app_state diff --git a/uvicorn/server.py b/uvicorn/server.py index f14026f16..e1789c795 100644 --- a/uvicorn/server.py +++ b/uvicorn/server.py @@ -2,7 +2,6 @@ import asyncio import contextlib -import logging import os import platform import signal @@ -33,8 +32,6 @@ if sys.platform == "win32": # pragma: py-not-win32 HANDLED_SIGNALS += (signal.SIGBREAK,) # Windows signal 21. Sent by Ctrl+Break. -logger = logging.getLogger("uvicorn.error") - class ServerState: """ @@ -79,7 +76,7 @@ async def _serve(self, sockets: list[socket.socket] | None = None) -> None: message = "Started server process [%d]" color_message = "Started server process [" + click.style("%d", fg="cyan") + "]" - logger.info(message, process_id, extra={"color_message": color_message}) + self.config.get_logger("general").info(message, process_id, extra={"color_message": color_message}) await self.startup(sockets=sockets) if self.should_exit: @@ -89,7 +86,7 @@ async def _serve(self, sockets: list[socket.socket] | None = None) -> None: message = "Finished server process [%d]" color_message = "Finished server process [" + click.style("%d", fg="cyan") + "]" - logger.info(message, process_id, extra={"color_message": color_message}) + self.config.get_logger("general").info(message, process_id, extra={"color_message": color_message}) async def startup(self, sockets: list[socket.socket] | None = None) -> None: await self.lifespan.startup() @@ -167,7 +164,7 @@ def _share_socket( backlog=config.backlog, ) except OSError as exc: - logger.error(exc) + self.config.get_logger("general").error(exc) await self.lifespan.shutdown() sys.exit(1) @@ -189,13 +186,16 @@ def _log_started_message(self, listeners: Sequence[socket.SocketType]) -> None: if config.fd is not None: # pragma: py-win32 sock = listeners[0] - logger.info( + self.config.get_logger("general").info( "Uvicorn running on socket %s (Press CTRL+C to quit)", sock.getsockname(), ) elif config.uds is not None: # pragma: py-win32 - logger.info("Uvicorn running on unix socket %s (Press CTRL+C to quit)", config.uds) + self.config.get_logger("general").info( + "Uvicorn running on unix socket %s (Press CTRL+C to quit)", + config.uds, + ) else: addr_format = "%s://%s:%d" @@ -211,7 +211,7 @@ def _log_started_message(self, listeners: Sequence[socket.SocketType]) -> None: protocol_name = "https" if config.ssl else "http" message = f"Uvicorn running on {addr_format} (Press CTRL+C to quit)" color_message = "Uvicorn running on " + click.style(addr_format, bold=True) + " (Press CTRL+C to quit)" - logger.info( + self.config.get_logger("general").info( message, protocol_name, host, @@ -253,13 +253,15 @@ async def on_tick(self, counter: int) -> bool: max_requests = self.config.limit_max_requests if max_requests is not None and self.server_state.total_requests >= max_requests: - logger.warning(f"Maximum request limit of {max_requests} exceeded. Terminating process.") + self.config.get_logger("general").warning( + f"Maximum request limit of {max_requests} exceeded. Terminating process." + ) return True return False async def shutdown(self, sockets: list[socket.socket] | None = None) -> None: - logger.info("Shutting down") + self.config.get_logger("general").info("Shutting down") # Stop accepting new connections. for server in self.servers: @@ -279,7 +281,7 @@ async def shutdown(self, sockets: list[socket.socket] | None = None) -> None: timeout=self.config.timeout_graceful_shutdown, ) except asyncio.TimeoutError: - logger.error( + self.config.get_logger("general").error( "Cancel %s running task(s), timeout graceful shutdown exceeded", len(self.server_state.tasks), ) @@ -297,14 +299,14 @@ async def _wait_tasks_to_complete(self) -> None: # Wait for existing connections to finish sending responses. if self.server_state.connections and not self.force_exit: msg = "Waiting for connections to close. (CTRL+C to force quit)" - logger.info(msg) + self.config.get_logger("general").info(msg) while self.server_state.connections and not self.force_exit: await asyncio.sleep(0.1) # Wait for existing tasks to complete. if self.server_state.tasks and not self.force_exit: msg = "Waiting for background tasks to complete. (CTRL+C to force quit)" - logger.info(msg) + self.config.get_logger("general").info(msg) while self.server_state.tasks and not self.force_exit: await asyncio.sleep(0.1) diff --git a/uvicorn/supervisors/basereload.py b/uvicorn/supervisors/basereload.py index f07ca3912..f353897c0 100644 --- a/uvicorn/supervisors/basereload.py +++ b/uvicorn/supervisors/basereload.py @@ -1,6 +1,5 @@ from __future__ import annotations -import logging import os import signal import sys @@ -20,8 +19,6 @@ signal.SIGTERM, # Unix signal 15. Sent by `kill `. ) -logger = logging.getLogger("uvicorn.error") - class BaseReload: def __init__( @@ -51,7 +48,7 @@ def run(self) -> None: self.startup() for changes in self: if changes: - logger.warning( + self.config.get_logger("general").warning( "%s detected changes in %s. Reloading...", self.reloader_name, ", ".join(map(_display_path, changes)), @@ -76,7 +73,7 @@ def startup(self) -> None: click.style(str(self.pid), fg="cyan", bold=True), click.style(str(self.reloader_name), fg="cyan", bold=True), ) - logger.info(message, extra={"color_message": color_message}) + self.config.get_logger("general").info(message, extra={"color_message": color_message}) for sig in HANDLED_SIGNALS: signal.signal(sig, self.signal_handler) @@ -108,7 +105,7 @@ def shutdown(self) -> None: message = f"Stopping reloader process [{str(self.pid)}]" color_message = "Stopping reloader process [{}]".format(click.style(str(self.pid), fg="cyan", bold=True)) - logger.info(message, extra={"color_message": color_message}) + self.config.get_logger("general").info(message, extra={"color_message": color_message}) def should_restart(self) -> list[Path] | None: raise NotImplementedError("Reload strategies should override should_restart()") diff --git a/uvicorn/supervisors/multiprocess.py b/uvicorn/supervisors/multiprocess.py index e198fe780..0c1801ca6 100644 --- a/uvicorn/supervisors/multiprocess.py +++ b/uvicorn/supervisors/multiprocess.py @@ -1,6 +1,5 @@ from __future__ import annotations -import logging import os import signal import threading @@ -19,8 +18,6 @@ if hasattr(signal, f"SIG{x}") } -logger = logging.getLogger("uvicorn.error") - class Process: def __init__( @@ -29,6 +26,7 @@ def __init__( target: Callable[[list[socket] | None], None], sockets: list[socket], ) -> None: + self.config = config self.real_target = target self.parent_conn, self.child_conn = Pipe() @@ -80,7 +78,7 @@ def terminate(self) -> None: os.kill(self.process.pid, signal.CTRL_BREAK_EVENT) # type: ignore[attr-defined] else: os.kill(self.process.pid, signal.SIGTERM) - logger.info(f"Terminated child process [{self.process.pid}]") + self.config.get_logger("general").info(f"Terminated child process [{self.process.pid}]") self.parent_conn.close() self.child_conn.close() @@ -91,7 +89,7 @@ def kill(self) -> None: self.process.kill() def join(self) -> None: - logger.info(f"Waiting for child process [{self.process.pid}]") + self.config.get_logger("general").info(f"Waiting for child process [{self.process.pid}]") self.process.join() @property @@ -144,7 +142,7 @@ def restart_all(self) -> None: def run(self) -> None: message = f"Started parent process [{os.getpid()}]" color_message = "Started parent process [{}]".format(click.style(str(os.getpid()), fg="cyan", bold=True)) - logger.info(message, extra={"color_message": color_message}) + self.config.get_logger("general").info(message, extra={"color_message": color_message}) self.init_processes() @@ -157,7 +155,7 @@ def run(self) -> None: message = f"Stopping parent process [{os.getpid()}]" color_message = "Stopping parent process [{}]".format(click.style(str(os.getpid()), fg="cyan", bold=True)) - logger.info(message, extra={"color_message": color_message}) + self.config.get_logger("general").info(message, extra={"color_message": color_message}) def keep_subprocess_alive(self) -> None: if self.should_exit.is_set(): @@ -173,7 +171,7 @@ def keep_subprocess_alive(self) -> None: if self.should_exit.is_set(): return # pragma: full coverage - logger.info(f"Child process [{process.pid}] died") + self.config.get_logger("general").info(f"Child process [{process.pid}] died") process = Process(self.config, self.target, self.sockets) process.start() self.processes[idx] = process @@ -186,35 +184,39 @@ def handle_signals(self) -> None: if sig_handler is not None: sig_handler() else: # pragma: no cover - logger.debug(f"Received signal {sig_name}, but no handler is defined for it.") + self.config.get_logger("general").debug( + f"Received signal {sig_name}, but no handler is defined for it." + ) def handle_int(self) -> None: - logger.info("Received SIGINT, exiting.") + self.config.get_logger("general").info("Received SIGINT, exiting.") self.should_exit.set() def handle_term(self) -> None: - logger.info("Received SIGTERM, exiting.") + self.config.get_logger("general").info("Received SIGTERM, exiting.") self.should_exit.set() def handle_break(self) -> None: # pragma: py-not-win32 - logger.info("Received SIGBREAK, exiting.") + self.config.get_logger("general").info("Received SIGBREAK, exiting.") self.should_exit.set() def handle_hup(self) -> None: # pragma: py-win32 - logger.info("Received SIGHUP, restarting processes.") + self.config.get_logger("general").info("Received SIGHUP, restarting processes.") self.restart_all() def handle_ttin(self) -> None: # pragma: py-win32 - logger.info("Received SIGTTIN, increasing the number of processes.") + self.config.get_logger("general").info("Received SIGTTIN, increasing the number of processes.") self.processes_num += 1 process = Process(self.config, self.target, self.sockets) process.start() self.processes.append(process) def handle_ttou(self) -> None: # pragma: py-win32 - logger.info("Received SIGTTOU, decreasing number of processes.") + self.config.get_logger("general").info("Received SIGTTOU, decreasing number of processes.") if self.processes_num <= 1: - logger.info("Already reached one process, cannot decrease the number of processes anymore.") + self.config.get_logger("general").info( + "Already reached one process, cannot decrease the number of processes anymore." + ) return self.processes_num -= 1 process = self.processes.pop() diff --git a/uvicorn/supervisors/statreload.py b/uvicorn/supervisors/statreload.py index 70d0a6d5c..a78835f89 100644 --- a/uvicorn/supervisors/statreload.py +++ b/uvicorn/supervisors/statreload.py @@ -1,6 +1,5 @@ from __future__ import annotations -import logging from pathlib import Path from socket import socket from typing import Callable, Iterator @@ -8,8 +7,6 @@ from uvicorn.config import Config from uvicorn.supervisors.basereload import BaseReload -logger = logging.getLogger("uvicorn.error") - class StatReload(BaseReload): def __init__( @@ -23,7 +20,9 @@ def __init__( self.mtimes: dict[Path, float] = {} if config.reload_excludes or config.reload_includes: - logger.warning("--reload-include and --reload-exclude have no effect unless " "watchfiles is installed.") + self.config.get_logger("general").warning( + "--reload-include and --reload-exclude have no effect unless " "watchfiles is installed." + ) def should_restart(self) -> list[Path] | None: self.pause() diff --git a/uvicorn/supervisors/watchgodreload.py b/uvicorn/supervisors/watchgodreload.py index 6f248faa7..c6be32ccb 100644 --- a/uvicorn/supervisors/watchgodreload.py +++ b/uvicorn/supervisors/watchgodreload.py @@ -1,6 +1,5 @@ from __future__ import annotations -import logging import warnings from pathlib import Path from socket import socket @@ -16,11 +15,10 @@ DirEntry = os.DirEntry[str] -logger = logging.getLogger("uvicorn.error") - class CustomWatcher(DefaultWatcher): def __init__(self, root_path: Path, config: Config): + self.config = config default_includes = ["*.py"] self.includes = [default for default in default_includes if default not in config.reload_excludes] self.includes.extend(config.reload_includes) @@ -85,7 +83,7 @@ def should_watch_dir(self, entry: DirEntry) -> bool: is_watched = True if is_watched: - logger.debug( + self.config.get_logger("general").debug( "WatchGodReload detected a new excluded dir '%s' in '%s'; " "Adding to exclude list.", entry_path.relative_to(self.resolved_root), str(self.resolved_root), @@ -105,7 +103,7 @@ def should_watch_dir(self, entry: DirEntry) -> bool: for include_pattern in self.includes: if entry_path.match(include_pattern): - logger.info( + self.config.get_logger("general").info( "WatchGodReload detected a new reload dir '%s' in '%s'; " "Adding to watch list.", str(entry_path.relative_to(self.resolved_root)), str(self.resolved_root), diff --git a/uvicorn/workers.py b/uvicorn/workers.py index 061805b6c..d3378d146 100644 --- a/uvicorn/workers.py +++ b/uvicorn/workers.py @@ -1,7 +1,6 @@ from __future__ import annotations import asyncio -import logging import signal import sys import warnings @@ -31,16 +30,6 @@ class UvicornWorker(Worker): def __init__(self, *args: Any, **kwargs: Any) -> None: super().__init__(*args, **kwargs) - logger = logging.getLogger("uvicorn.error") - logger.handlers = self.log.error_log.handlers - logger.setLevel(self.log.error_log.level) - logger.propagate = False - - logger = logging.getLogger("uvicorn.access") - logger.handlers = self.log.access_log.handlers - logger.setLevel(self.log.access_log.level) - logger.propagate = False - config_kwargs: dict = { "app": None, "log_config": None, @@ -70,6 +59,16 @@ def __init__(self, *args: Any, **kwargs: Any) -> None: self.config = Config(**config_kwargs) + logger = self.config.get_logger("general") + logger.handlers = self.log.error_log.handlers + logger.setLevel(self.log.error_log.level) + logger.propagate = False + + logger = self.config.get_logger("access") + logger.handlers = self.log.access_log.handlers + logger.setLevel(self.log.access_log.level) + logger.propagate = False + def init_process(self) -> None: self.config.setup_event_loop() super().init_process()