From 123845576a9e47a869b7fff1ad053f2e9501ff01 Mon Sep 17 00:00:00 2001 From: Tom Christie Date: Thu, 31 Oct 2019 15:00:47 +0000 Subject: [PATCH] Add 'trace' log level --- tests/middleware/test_message_logger.py | 19 ++++++++++-------- uvicorn/config.py | 8 +++++++- uvicorn/logging.py | 5 ++++- uvicorn/middleware/message_logger.py | 25 +++++++++++++++--------- uvicorn/protocols/http/h11_impl.py | 10 ++++++---- uvicorn/protocols/http/httptools_impl.py | 10 ++++++---- 6 files changed, 50 insertions(+), 27 deletions(-) diff --git a/tests/middleware/test_message_logger.py b/tests/middleware/test_message_logger.py index 6d5eab1ee..73a03fb14 100644 --- a/tests/middleware/test_message_logger.py +++ b/tests/middleware/test_message_logger.py @@ -1,10 +1,10 @@ -import logging - import pytest from tests.client import TestClient from uvicorn.middleware.message_logger import MessageLoggerMiddleware +TRACE_LOG_LEVEL = 5 + def test_message_logger(caplog): async def app(scope, receive, send): @@ -12,15 +12,17 @@ async def app(scope, receive, send): await send({"type": "http.response.start", "status": 200, "headers": []}) await send({"type": "http.response.body", "body": b"", "more_body": False}) - caplog.set_level(logging.DEBUG, logger="uvicorn.error") + caplog.set_level(TRACE_LOG_LEVEL, logger="uvicorn.asgi") + caplog.set_level(TRACE_LOG_LEVEL) + app = MessageLoggerMiddleware(app) client = TestClient(app) response = client.get("/") assert response.status_code == 200 messages = [record.msg % record.args for record in caplog.records] assert sum(["ASGI [1] Started" in message for message in messages]) == 1 - assert sum(["ASGI [1] Sent" in message for message in messages]) == 1 - assert sum(["ASGI [1] Received" in message for message in messages]) == 2 + assert sum(["ASGI [1] Send" in message for message in messages]) == 2 + assert sum(["ASGI [1] Receive" in message for message in messages]) == 1 assert sum(["ASGI [1] Completed" in message for message in messages]) == 1 assert sum(["ASGI [1] Raised exception" in message for message in messages]) == 0 @@ -29,14 +31,15 @@ def test_message_logger_exc(caplog): async def app(scope, receive, send): raise RuntimeError() - caplog.set_level(logging.DEBUG, logger="uvicorn.error") + caplog.set_level(TRACE_LOG_LEVEL, logger="uvicorn.asgi") + caplog.set_level(TRACE_LOG_LEVEL) app = MessageLoggerMiddleware(app) client = TestClient(app) with pytest.raises(RuntimeError): client.get("/") messages = [record.msg % record.args for record in caplog.records] assert sum(["ASGI [1] Started" in message for message in messages]) == 1 - assert sum(["ASGI [1] Sent" in message for message in messages]) == 0 - assert sum(["ASGI [1] Received" in message for message in messages]) == 0 + assert sum(["ASGI [1] Send" in message for message in messages]) == 0 + assert sum(["ASGI [1] Receive" in message for message in messages]) == 0 assert sum(["ASGI [1] Completed" in message for message in messages]) == 0 assert sum(["ASGI [1] Raised exception" in message for message in messages]) == 1 diff --git a/uvicorn/config.py b/uvicorn/config.py index b08792ae3..bc5e8aa64 100644 --- a/uvicorn/config.py +++ b/uvicorn/config.py @@ -18,12 +18,15 @@ from uvicorn.middleware.proxy_headers import ProxyHeadersMiddleware from uvicorn.middleware.wsgi import WSGIMiddleware +TRACE_LOG_LEVEL = 5 + LOG_LEVELS = { "critical": logging.CRITICAL, "error": logging.ERROR, "warning": logging.WARNING, "info": logging.INFO, "debug": logging.DEBUG, + "trace": TRACE_LOG_LEVEL, } HTTP_PROTOCOLS = { "auto": "uvicorn.protocols.http.auto:AutoHTTPProtocol", @@ -196,6 +199,8 @@ def is_ssl(self) -> bool: return bool(self.ssl_keyfile or self.ssl_certfile) def configure_logging(self): + logging.addLevelName(TRACE_LOG_LEVEL, "TRACE") + if sys.version_info < (3, 7): # https://bugs.python.org/issue30520 import pickle @@ -224,6 +229,7 @@ def __reduce__(self): logging.getLogger("").setLevel(log_level) logging.getLogger("uvicorn.error").setLevel(log_level) logging.getLogger("uvicorn.access").setLevel(log_level) + logging.getLogger("uvicorn.asgi").setLevel(log_level) if self.access_log is False: logging.getLogger("uvicorn.access").handlers = [] logging.getLogger("uvicorn.access").propagate = False @@ -289,7 +295,7 @@ def load(self): if self.debug: self.loaded_app = DebugMiddleware(self.loaded_app) - if logger.level <= logging.DEBUG: + if logger.level <= TRACE_LOG_LEVEL: self.loaded_app = MessageLoggerMiddleware(self.loaded_app) if self.proxy_headers: self.loaded_app = ProxyHeadersMiddleware( diff --git a/uvicorn/logging.py b/uvicorn/logging.py index 92ce378b5..12c49aae8 100644 --- a/uvicorn/logging.py +++ b/uvicorn/logging.py @@ -4,6 +4,8 @@ import click +TRACE_LOG_LEVEL = 5 + class ColourizedFormatter(logging.Formatter): """ @@ -15,7 +17,8 @@ class ColourizedFormatter(logging.Formatter): """ level_name_colors = { - logging.DEBUG: lambda level_name: click.style(str(level_name), fg="blue"), + TRACE_LOG_LEVEL: lambda level_name: click.style(str(level_name), fg="blue"), + logging.DEBUG: lambda level_name: click.style(str(level_name), fg="cyan"), logging.INFO: lambda level_name: click.style(str(level_name), fg="green"), logging.WARNING: lambda level_name: click.style(str(level_name), fg="yellow"), logging.ERROR: lambda level_name: click.style(str(level_name), fg="red"), diff --git a/uvicorn/middleware/message_logger.py b/uvicorn/middleware/message_logger.py index 453b0c8fb..6e7916bb6 100644 --- a/uvicorn/middleware/message_logger.py +++ b/uvicorn/middleware/message_logger.py @@ -6,6 +6,7 @@ "text": "<{length} chars>", "headers": "<...>", } +TRACE_LOG_LEVEL = 5 def message_with_placeholders(message): @@ -26,7 +27,12 @@ class MessageLoggerMiddleware: def __init__(self, app): self.task_counter = 0 self.app = app - self.logger = logging.getLogger("uvicorn.error") + self.logger = logging.getLogger("uvicorn.asgi") + + def trace(message, *args, **kwargs): + logging.log(TRACE_LOG_LEVEL, message, *args, **kwargs) + + self.logger.trace = trace async def __call__(self, scope, receive, send): self.task_counter += 1 @@ -38,24 +44,25 @@ async def __call__(self, scope, receive, send): async def inner_receive(): message = await receive() logged_message = message_with_placeholders(message) - log_text = "%s [%d] Sent %s" - self.logger.debug(log_text, prefix, task_counter, logged_message) + log_text = "%s [%d] Receive %s" + self.logger.trace(log_text, prefix, task_counter, logged_message) return message async def inner_send(message): logged_message = message_with_placeholders(message) - log_text = "%s [%d] Received %s" - self.logger.debug(log_text, prefix, task_counter, logged_message) + log_text = "%s [%d] Send %s" + self.logger.trace(log_text, prefix, task_counter, logged_message) await send(message) - log_text = "%s [%d] Started" - self.logger.debug(log_text, prefix, task_counter) + logged_scope = message_with_placeholders(scope) + log_text = "%s [%d] Started scope=%s" + self.logger.trace(log_text, prefix, task_counter, logged_scope) try: await self.app(scope, inner_receive, inner_send) except BaseException as exc: log_text = "%s [%d] Raised exception" - self.logger.debug(log_text, prefix, task_counter) + self.logger.trace(log_text, prefix, task_counter) raise exc from None else: log_text = "%s [%d] Completed" - self.logger.debug(log_text, prefix, task_counter) + self.logger.trace(log_text, prefix, task_counter) diff --git a/uvicorn/protocols/http/h11_impl.py b/uvicorn/protocols/http/h11_impl.py index 84020bb70..027e9fe58 100644 --- a/uvicorn/protocols/http/h11_impl.py +++ b/uvicorn/protocols/http/h11_impl.py @@ -27,6 +27,8 @@ def _get_status_phrase(status_code): HIGH_WATER_LIMIT = 65536 +TRACE_LOG_LEVEL = 5 + class FlowControl: def __init__(self, transport): @@ -123,16 +125,16 @@ def connection_made(self, transport): self.client = get_remote_addr(transport) self.scheme = "https" if is_ssl(transport) else "http" - if self.logger.level <= logging.DEBUG: + if self.logger.level <= TRACE_LOG_LEVEL: prefix = "%s:%d - " % tuple(self.client) if self.client else "" - self.logger.debug("%sConnected", prefix) + self.logger.log(TRACE_LOG_LEVEL, "%sConnection made", prefix) def connection_lost(self, exc): self.connections.discard(self) - if self.logger.level <= logging.DEBUG: + if self.logger.level <= TRACE_LOG_LEVEL: prefix = "%s:%d - " % tuple(self.client) if self.client else "" - self.logger.debug("%sDisconnected", prefix) + self.logger.log(TRACE_LOG_LEVEL, "%Connection lost", prefix) if self.cycle and not self.cycle.response_complete: self.cycle.disconnected = True diff --git a/uvicorn/protocols/http/httptools_impl.py b/uvicorn/protocols/http/httptools_impl.py index 635649c5e..3289bdf95 100644 --- a/uvicorn/protocols/http/httptools_impl.py +++ b/uvicorn/protocols/http/httptools_impl.py @@ -28,6 +28,8 @@ def _get_status_line(status_code): HIGH_WATER_LIMIT = 65536 +TRACE_LOG_LEVEL = 5 + class FlowControl: def __init__(self, transport): @@ -127,16 +129,16 @@ def connection_made(self, transport): self.client = get_remote_addr(transport) self.scheme = "https" if is_ssl(transport) else "http" - if self.logger.level <= logging.DEBUG: + if self.logger.level <= TRACE_LOG_LEVEL: prefix = "%s:%d - " % tuple(self.client) if self.client else "" - self.logger.debug("%sConnected", prefix) + self.logger.log(TRACE_LOG_LEVEL, "%sConnection made", prefix) def connection_lost(self, exc): self.connections.discard(self) - if self.logger.level <= logging.DEBUG: + if self.logger.level <= TRACE_LOG_LEVEL: prefix = "%s:%d - " % tuple(self.client) if self.client else "" - self.logger.debug("%sDisconnected", prefix) + self.logger.log(TRACE_LOG_LEVEL, "%sConnection lost", prefix) if self.cycle and not self.cycle.response_complete: self.cycle.disconnected = True