Add 'trace' log level

tests/middleware/test_message_logger.py

@@ -1,26 +1,28 @@
-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):
         message = await receive()
         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

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(

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"),

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)

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

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