From b347e691bfc604e7061716ab518def8ad5888c42 Mon Sep 17 00:00:00 2001 From: Marcelo Trylesinski Date: Sun, 15 May 2022 19:37:02 +0200 Subject: [PATCH 1/3] Refactor uvicorn logger setup --- tests/middleware/test_logging.py | 17 ++++++++++------- tests/protocols/test_http.py | 4 ++-- tests/test_config.py | 6 ++++-- tests/test_lifespan.py | 4 ++-- tests/test_main.py | 2 +- uvicorn/config.py | 10 +++++++--- uvicorn/lifespan/on.py | 2 +- uvicorn/loops/asyncio.py | 2 +- uvicorn/main.py | 4 ++-- uvicorn/protocols/http/h11_impl.py | 2 +- uvicorn/protocols/http/httptools_impl.py | 2 +- uvicorn/protocols/websockets/websockets_impl.py | 2 +- uvicorn/protocols/websockets/wsproto_impl.py | 2 +- uvicorn/server.py | 2 +- uvicorn/supervisors/basereload.py | 2 +- uvicorn/supervisors/multiprocess.py | 2 +- uvicorn/supervisors/statreload.py | 2 +- uvicorn/supervisors/watchgodreload.py | 3 ++- uvicorn/workers.py | 2 +- 19 files changed, 41 insertions(+), 31 deletions(-) diff --git a/tests/middleware/test_logging.py b/tests/middleware/test_logging.py index 1b183f85c..14118b6df 100644 --- a/tests/middleware/test_logging.py +++ b/tests/middleware/test_logging.py @@ -66,15 +66,13 @@ async def test_trace_logging_on_http_protocol(http_protocol, caplog, logging_con http=http_protocol, log_config=logging_config, ) - with caplog_for_logger(caplog, "uvicorn.error"): + with caplog_for_logger(caplog, "uvicorn.http"): async with run_server(config): async with httpx.AsyncClient() as client: response = await client.get("http://127.0.0.1:8000") assert response.status_code == 204 messages = [ - record.message - for record in caplog.records - if record.name == "uvicorn.error" + record.message for record in caplog.records if record.name == "uvicorn.http" ] assert any(" - HTTP connection made" in message for message in messages) assert any(" - HTTP connection lost" in message for message in messages) @@ -102,16 +100,21 @@ async def open_connection(url): log_config=logging_config, ws=ws_protocol, ) - with caplog_for_logger(caplog, "uvicorn.error"): + with caplog_for_logger(caplog, "uvicorn.http"), caplog_for_logger( + caplog, "uvicorn.websockets" + ): async with run_server(config): is_open = await open_connection("ws://127.0.0.1:8000") assert is_open + messages = [ + record.message for record in caplog.records if record.name == "uvicorn.http" + ] + assert any(" - Upgrading to WebSocket" in message for message in messages) messages = [ record.message for record in caplog.records - if record.name == "uvicorn.error" + if record.name == "uvicorn.websockets" ] - 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) diff --git a/tests/protocols/test_http.py b/tests/protocols/test_http.py index def8a3a88..468872f80 100644 --- a/tests/protocols/test_http.py +++ b/tests/protocols/test_http.py @@ -808,8 +808,8 @@ async def test_invalid_http_request(request_line, protocol_cls, caplog): app = Response("Hello, world", media_type="text/plain") request = INVALID_REQUEST_TEMPLATE % request_line - caplog.set_level(logging.INFO, logger="uvicorn.error") - logging.getLogger("uvicorn.error").propagate = True + caplog.set_level(logging.INFO, logger="uvicorn.http") + logging.getLogger("uvicorn.http").propagate = True protocol = get_connected_protocol(app, protocol_cls) protocol.data_received(request) diff --git a/tests/test_config.py b/tests/test_config.py index 403112f2c..c7008eb0f 100644 --- a/tests/test_config.py +++ b/tests/test_config.py @@ -254,7 +254,7 @@ def test_app_unimportable_other(caplog: pytest.LogCaptureFixture) -> None: error_messages = [ record.message for record in caplog.records - if record.name == "uvicorn.error" and record.levelname == "ERROR" + if record.name == "uvicorn.server" and record.levelname == "ERROR" ] assert ( 'Error loading ASGI app. Attribute "app" not found in module "tests.test_config".' # noqa: E501 @@ -485,8 +485,10 @@ def test_config_log_level(log_level: int) -> None: config = Config(app=asgi_app, log_level=log_level) config.load() - assert logging.getLogger("uvicorn.error").level == log_level + assert logging.getLogger("uvicorn.server").level == log_level assert logging.getLogger("uvicorn.access").level == log_level + assert logging.getLogger("uvicorn.http").level == log_level + assert logging.getLogger("uvicorn.websockets").level == log_level assert logging.getLogger("uvicorn.asgi").level == log_level assert config.log_level == log_level diff --git a/tests/test_lifespan.py b/tests/test_lifespan.py index d49a9dcf9..0a78ac2d2 100644 --- a/tests/test_lifespan.py +++ b/tests/test_lifespan.py @@ -155,7 +155,7 @@ async def test(): error_messages = [ record.message for record in caplog.records - if record.name == "uvicorn.error" and record.levelname == "ERROR" + if record.name == "uvicorn.server" and record.levelname == "ERROR" ] assert "the lifespan event failed" in error_messages.pop(0) assert "Application startup failed. Exiting." in error_messages.pop(0) @@ -240,7 +240,7 @@ async def test(): error_messages = [ record.message for record in caplog.records - if record.name == "uvicorn.error" and record.levelname == "ERROR" + if record.name == "uvicorn.server" and record.levelname == "ERROR" ] assert "the lifespan event failed" in error_messages.pop(0) assert "Application shutdown failed. Exiting." in error_messages.pop(0) diff --git a/tests/test_main.py b/tests/test_main.py index e8cf8acc5..0b384b067 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -90,7 +90,7 @@ def test_run_invalid_app_config_combination(caplog: pytest.LogCaptureFixture) -> with pytest.raises(SystemExit) as exit_exception: run(app, reload=True) assert exit_exception.value.code == 1 - assert caplog.records[-1].name == "uvicorn.error" + assert caplog.records[-1].name == "uvicorn.server" assert caplog.records[-1].levelno == WARNING assert caplog.records[-1].message == ( "You must pass the application as an import string to enable " diff --git a/uvicorn/config.py b/uvicorn/config.py index df91a6c4d..ef007a422 100644 --- a/uvicorn/config.py +++ b/uvicorn/config.py @@ -117,12 +117,14 @@ }, "loggers": { "uvicorn": {"handlers": ["default"], "level": "INFO", "propagate": False}, - "uvicorn.error": {"level": "INFO"}, + "uvicorn.server": {"level": "INFO"}, + "uvicorn.websockets": {"level": "INFO"}, + "uvicorn.http": {"level": "INFO"}, "uvicorn.access": {"handlers": ["access"], "level": "INFO", "propagate": False}, }, } -logger = logging.getLogger("uvicorn.error") +logger = logging.getLogger("uvicorn.server") def create_ssl_context( @@ -422,8 +424,10 @@ 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.server").setLevel(log_level) logging.getLogger("uvicorn.access").setLevel(log_level) + logging.getLogger("uvicorn.http").setLevel(log_level) + logging.getLogger("uvicorn.websockets").setLevel(log_level) logging.getLogger("uvicorn.asgi").setLevel(log_level) if self.access_log is False: logging.getLogger("uvicorn.access").handlers = [] diff --git a/uvicorn/lifespan/on.py b/uvicorn/lifespan/on.py index 0c650aab1..417a917f5 100644 --- a/uvicorn/lifespan/on.py +++ b/uvicorn/lifespan/on.py @@ -34,7 +34,7 @@ def __init__(self, config: Config) -> None: config.load() self.config = config - self.logger = logging.getLogger("uvicorn.error") + self.logger = logging.getLogger("uvicorn.server") 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 867545f2a..a8f18dc16 100644 --- a/uvicorn/loops/asyncio.py +++ b/uvicorn/loops/asyncio.py @@ -2,7 +2,7 @@ import logging import sys -logger = logging.getLogger("uvicorn.error") +logger = logging.getLogger("uvicorn.server") def asyncio_setup(use_subprocess: bool = False) -> None: # pragma: no cover diff --git a/uvicorn/main.py b/uvicorn/main.py index 3c59fa131..127771acb 100644 --- a/uvicorn/main.py +++ b/uvicorn/main.py @@ -41,7 +41,7 @@ STARTUP_FAILURE = 3 -logger = logging.getLogger("uvicorn.error") +logger = logging.getLogger("uvicorn.server") def print_version(ctx: click.Context, param: click.Parameter, value: bool) -> None: @@ -552,7 +552,7 @@ def run( server = Server(config=config) if (config.reload or config.workers > 1) and not isinstance(app, str): - logger = logging.getLogger("uvicorn.error") + logger = logging.getLogger("uvicorn.server") logger.warning( "You must pass the application as an import string to enable 'reload' or " "'workers'." diff --git a/uvicorn/protocols/http/h11_impl.py b/uvicorn/protocols/http/h11_impl.py index 9f6931ec5..b59c17e3b 100644 --- a/uvicorn/protocols/http/h11_impl.py +++ b/uvicorn/protocols/http/h11_impl.py @@ -76,7 +76,7 @@ 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.logger = logging.getLogger("uvicorn.http") self.access_logger = logging.getLogger("uvicorn.access") self.access_log = self.access_logger.hasHandlers() self.conn = h11.Connection(h11.SERVER, config.h11_max_incomplete_event_size) diff --git a/uvicorn/protocols/http/httptools_impl.py b/uvicorn/protocols/http/httptools_impl.py index 734e8945d..366aac4dc 100644 --- a/uvicorn/protocols/http/httptools_impl.py +++ b/uvicorn/protocols/http/httptools_impl.py @@ -74,7 +74,7 @@ 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.logger = logging.getLogger("uvicorn.http") self.access_logger = logging.getLogger("uvicorn.access") self.access_log = self.access_logger.hasHandlers() self.parser = httptools.HttpRequestParser(self) diff --git a/uvicorn/protocols/websockets/websockets_impl.py b/uvicorn/protocols/websockets/websockets_impl.py index b77485136..1b67ec07b 100644 --- a/uvicorn/protocols/websockets/websockets_impl.py +++ b/uvicorn/protocols/websockets/websockets_impl.py @@ -104,7 +104,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=logging.getLogger("uvicorn.websockets"), extra_headers=[], ) diff --git a/uvicorn/protocols/websockets/wsproto_impl.py b/uvicorn/protocols/websockets/wsproto_impl.py index 36005fede..954715daa 100644 --- a/uvicorn/protocols/websockets/wsproto_impl.py +++ b/uvicorn/protocols/websockets/wsproto_impl.py @@ -26,7 +26,7 @@ def __init__(self, config, server_state, _loop=None): self.config = config self.app = config.loaded_app self.loop = _loop or asyncio.get_event_loop() - self.logger = logging.getLogger("uvicorn.error") + self.logger = logging.getLogger("uvicorn.websockets") self.root_path = config.root_path # Shared server state diff --git a/uvicorn/server.py b/uvicorn/server.py index 494e2b658..72678d369 100644 --- a/uvicorn/server.py +++ b/uvicorn/server.py @@ -30,7 +30,7 @@ signal.SIGTERM, # Unix signal 15. Sent by `kill `. ) -logger = logging.getLogger("uvicorn.error") +logger = logging.getLogger("uvicorn.server") class ServerState: diff --git a/uvicorn/supervisors/basereload.py b/uvicorn/supervisors/basereload.py index b2d80d3ef..58672e542 100644 --- a/uvicorn/supervisors/basereload.py +++ b/uvicorn/supervisors/basereload.py @@ -17,7 +17,7 @@ signal.SIGTERM, # Unix signal 15. Sent by `kill `. ) -logger = logging.getLogger("uvicorn.error") +logger = logging.getLogger("uvicorn.server") class BaseReload: diff --git a/uvicorn/supervisors/multiprocess.py b/uvicorn/supervisors/multiprocess.py index 9ab4a742e..7937d0022 100644 --- a/uvicorn/supervisors/multiprocess.py +++ b/uvicorn/supervisors/multiprocess.py @@ -17,7 +17,7 @@ signal.SIGTERM, # Unix signal 15. Sent by `kill `. ) -logger = logging.getLogger("uvicorn.error") +logger = logging.getLogger("uvicorn.server") class Multiprocess: diff --git a/uvicorn/supervisors/statreload.py b/uvicorn/supervisors/statreload.py index 7cbcce310..bb730319c 100644 --- a/uvicorn/supervisors/statreload.py +++ b/uvicorn/supervisors/statreload.py @@ -6,7 +6,7 @@ from uvicorn.config import Config from uvicorn.supervisors.basereload import BaseReload -logger = logging.getLogger("uvicorn.error") +logger = logging.getLogger("uvicorn.server") class StatReload(BaseReload): diff --git a/uvicorn/supervisors/watchgodreload.py b/uvicorn/supervisors/watchgodreload.py index 1ec3dc596..074057890 100644 --- a/uvicorn/supervisors/watchgodreload.py +++ b/uvicorn/supervisors/watchgodreload.py @@ -14,7 +14,8 @@ DirEntry = os.DirEntry[str] -logger = logging.getLogger("uvicorn.error") + +logger = logging.getLogger("uvicorn.server") class CustomWatcher(DefaultWatcher): diff --git a/uvicorn/workers.py b/uvicorn/workers.py index c7d16ff6e..856a99721 100644 --- a/uvicorn/workers.py +++ b/uvicorn/workers.py @@ -22,7 +22,7 @@ class UvicornWorker(Worker): def __init__(self, *args: Any, **kwargs: Any) -> None: super(UvicornWorker, self).__init__(*args, **kwargs) - logger = logging.getLogger("uvicorn.error") + logger = logging.getLogger("uvicorn.server") logger.handlers = self.log.error_log.handlers logger.setLevel(self.log.error_log.level) logger.propagate = False From e23c673b49d11198b1821092e01ca6b4124f1464 Mon Sep 17 00:00:00 2001 From: Marcelo Trylesinski Date: Thu, 27 Oct 2022 11:26:12 +0200 Subject: [PATCH 2/3] Add logging page --- docs/index.md | 7 ++----- docs/logging.md | 1 + mkdocs.yml | 6 ++++++ 3 files changed, 9 insertions(+), 5 deletions(-) create mode 100644 docs/logging.md diff --git a/docs/index.md b/docs/index.md index 945b80772..1cd2f1a7a 100644 --- a/docs/index.md +++ b/docs/index.md @@ -205,8 +205,7 @@ There are several ways to run uvicorn directly from your application. If you're looking for a programmatic equivalent of the `uvicorn` command line interface, use `uvicorn.run()`: -```python -# main.py +```py title="main.py" import uvicorn async def app(scope, receive, send): @@ -275,9 +274,7 @@ For more information, see the [deployment documentation](deployment.md). The `--factory` flag allows loading the application from a factory function, rather than an application instance directly. The factory will be called with no arguments and should return an ASGI application. -**example.py**: - -```python +```py title="example.py" def create_app(): app = ... return app diff --git a/docs/logging.md b/docs/logging.md new file mode 100644 index 000000000..85f805b3b --- /dev/null +++ b/docs/logging.md @@ -0,0 +1 @@ +# Logging \ No newline at end of file diff --git a/mkdocs.yml b/mkdocs.yml index ed833a10c..f6a69a7b9 100644 --- a/mkdocs.yml +++ b/mkdocs.yml @@ -24,12 +24,18 @@ edit_uri: "" nav: - Introduction: "index.md" - Settings: "settings.md" + - Logging: "logging.md" - Deployment: "deployment.md" - Server Behavior: "server-behavior.md" - Contributing: "contributing.md" markdown_extensions: - admonition + - pymdownx.highlight: + anchor_linenums: true + - pymdownx.inlinehilite + - pymdownx.snippets + - pymdownx.superfences - codehilite: css_class: highlight - toc: From af44ea9912ca3f08003e7c30bda419b2c73e2520 Mon Sep 17 00:00:00 2001 From: Marcelo Trylesinski Date: Thu, 27 Oct 2022 11:39:43 +0200 Subject: [PATCH 3/3] Add content to the documentation page --- docs/logging.md | 41 ++++++++++++++++++++++++++++++++++++++++- 1 file changed, 40 insertions(+), 1 deletion(-) diff --git a/docs/logging.md b/docs/logging.md index 85f805b3b..5b857f698 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -1 +1,40 @@ -# Logging \ No newline at end of file +# Logging + +Logging in Python is pretty complex, and there are many different ways to do it. +This document is intended to provide an overview about the logger objects available in **Uvicorn**. + +### Loggers + +**Uvicorn** has many loggers available, each one with a different purpose. + +It contains an ancestor logger called `uvicorn`, and then multiple children loggers. + +#### Server Logger (`uvicorn.server`) + +This logger is used to log information about the core server functionality, such as startup and shutdown. + +#### WebSocket Logger (`uvicorn.websocket`) + +This logger is used to log server-side information about WebSocket protocol messages. + +#### HTTP Logger (`uvicorn.http`) + +This logger is used to log server-side information about HTTP protocol messages. + +#### Access Logger (`uvicorn.access`) + +This logger is used to log client-side information about each request/response cycle. + +#### ASGI Logger (`uvicorn.asgi`) + +This logger is used to log low-level server-side ASGI messages. Only available when `--log-level` is set to `trace`. + +### Configuration + +**Uvicorn** uses the standard Python `logging` module to handle logging. + +This section will be used to teach people how to configure uvicorn loggers. + +### Tutorials + +This section will be used to link tutorials.