Move verbosity filtering to logger (#2453)

sanic/app.py

@@ -1573,8 +1573,9 @@ async def _server_event(
             "shutdown",
         ):
             raise SanicException(f"Invalid server event: {event}")
-        if self.state.verbosity >= 1:
-            logger.debug(f"Triggering server events: {event}")
+        logger.debug(
+            f"Triggering server events: {event}", extra={"verbosity": 1}
+        )
         reverse = concern == "shutdown"
         if loop is None:
             loop = self.loop

sanic/application/state.py

@@ -9,7 +9,7 @@
 from ssl import SSLContext
 from typing import TYPE_CHECKING, Any, Dict, List, Optional, Set, Union
 
-from sanic.log import logger
+from sanic.log import VerbosityFilter, logger
 from sanic.server.async_server import AsyncioServer
 
 
@@ -91,6 +91,9 @@ def set_mode(self, value: Union[str, Mode]):
         if getattr(self.app, "configure_logging", False) and self.app.debug:
             logger.setLevel(logging.DEBUG)
 
+    def set_verbosity(self, value: int):
+        VerbosityFilter.verbosity = value
+
     @property
     def is_debug(self):
         return self.mode is Mode.DEBUG

sanic/asgi.py

@@ -25,27 +25,28 @@ class Lifespan:
     def __init__(self, asgi_app: ASGIApp) -> None:
         self.asgi_app = asgi_app
 
-        if self.asgi_app.sanic_app.state.verbosity > 0:
-            if (
-                "server.init.before"
-                in self.asgi_app.sanic_app.signal_router.name_index
-            ):
-                logger.debug(
-                    'You have set a listener for "before_server_start" '
-                    "in ASGI mode. "
-                    "It will be executed as early as possible, but not before "
-                    "the ASGI server is started."
-                )
-            if (
-                "server.shutdown.after"
-                in self.asgi_app.sanic_app.signal_router.name_index
-            ):
-                logger.debug(
-                    'You have set a listener for "after_server_stop" '
-                    "in ASGI mode. "
-                    "It will be executed as late as possible, but not after "
-                    "the ASGI server is stopped."
-                )
+        if (
+            "server.init.before"
+            in self.asgi_app.sanic_app.signal_router.name_index
+        ):
+            logger.debug(
+                'You have set a listener for "before_server_start" '
+                "in ASGI mode. "
+                "It will be executed as early as possible, but not before "
+                "the ASGI server is started.",
+                extra={"verbosity": 1},
+            )
+        if (
+            "server.shutdown.after"
+            in self.asgi_app.sanic_app.signal_router.name_index
+        ):
+            logger.debug(
+                'You have set a listener for "after_server_stop" '
+                "in ASGI mode. "
+                "It will be executed as late as possible, but not after "
+                "the ASGI server is stopped.",
+                extra={"verbosity": 1},
+            )
 
     async def startup(self) -> None:
         """

sanic/log.py

@@ -61,21 +61,36 @@ class Colors(str, Enum):  # no cov
     END = "\033[0m"
     BLUE = "\033[01;34m"
     GREEN = "\033[01;32m"
-    YELLOW = "\033[01;33m"
+    PURPLE = "\033[01;35m"
     RED = "\033[01;31m"
+    SANIC = "\033[38;2;255;13;104m"
+    YELLOW = "\033[01;33m"
+
+
+class VerbosityFilter(logging.Filter):
+    verbosity: int = 0
+
+    def filter(self, record: logging.LogRecord) -> bool:
+        verbosity = getattr(record, "verbosity", 0)
+        return verbosity <= self.verbosity
+
 
+_verbosity_filter = VerbosityFilter()
 
 logger = logging.getLogger("sanic.root")  # no cov
+logger.addFilter(_verbosity_filter)
 """
 General Sanic logger
 """
 
 error_logger = logging.getLogger("sanic.error")  # no cov
+error_logger.addFilter(_verbosity_filter)
 """
 Logger used by Sanic for error logging
 """
 
 access_logger = logging.getLogger("sanic.access")  # no cov
+access_logger.addFilter(_verbosity_filter)
 """
 Logger used by Sanic for access logging
 """

sanic/touchup/schemes/ode.py

@@ -24,9 +24,7 @@ def run(self, method, module_globals):
         raw_source = getsource(method)
         src = dedent(raw_source)
         tree = parse(src)
-        node = RemoveDispatch(
-            self._registered_events, self.app.state.verbosity
-        ).visit(tree)
+        node = RemoveDispatch(self._registered_events).visit(tree)
         compiled_src = compile(node, method.__name__, "exec")
         exec_locals: Dict[str, Any] = {}
         exec(compiled_src, module_globals, exec_locals)  # nosec
@@ -64,9 +62,8 @@ async def noop(**_):  # no cov
 
 
 class RemoveDispatch(NodeTransformer):
-    def __init__(self, registered_events, verbosity: int = 0) -> None:
+    def __init__(self, registered_events) -> None:
         self._registered_events = registered_events
-        self._verbosity = verbosity
 
     def visit_Expr(self, node: Expr) -> Any:
         call = node.value
@@ -83,8 +80,10 @@ def visit_Expr(self, node: Expr) -> Any:
             if hasattr(event, "s"):
                 event_name = getattr(event, "value", event.s)
                 if self._not_registered(event_name):
-                    if self._verbosity >= 2:
-                        logger.debug(f"Disabling event: {event_name}")
+                    logger.debug(
+                        f"Disabling event: {event_name}",
+                        extra={"verbosity": 2},
+                    )
                     return None
         return node
 

tests/test_asgi.py

@@ -222,6 +222,7 @@ def install_signal_handlers(self):
     assert after_server_stop
 
     app.state.mode = Mode.DEBUG
+    app.state.verbosity = 0
     with caplog.at_level(logging.DEBUG):
         server.run()
 

tests/test_logging.py

@@ -209,3 +209,42 @@ async def handler(request):
             "request": f"GET {request.scheme}://{request.host}/",
         },
     )
+
+
+@pytest.mark.parametrize(
+    "app_verbosity,log_verbosity,exists",
+    (
+        (0, 0, True),
+        (0, 1, False),
+        (0, 2, False),
+        (1, 0, True),
+        (1, 1, True),
+        (1, 2, False),
+        (2, 0, True),
+        (2, 1, True),
+        (2, 2, True),
+    ),
+)
+def test_verbosity(app, caplog, app_verbosity, log_verbosity, exists):
+    rand_string = str(uuid.uuid4())
+
+    @app.get("/")
+    def log_info(request):
+        logger.info("DEFAULT")
+        logger.info(rand_string, extra={"verbosity": log_verbosity})
+        return text("hello")
+
+    with caplog.at_level(logging.INFO):
+        _ = app.test_client.get(
+            "/", server_kwargs={"verbosity": app_verbosity}
+        )
+
+    record = ("sanic.root", logging.INFO, rand_string)
+
+    if exists:
+        assert record in caplog.record_tuples
+    else:
+        assert record not in caplog.record_tuples
+
+    if app_verbosity == 0:
+        assert ("sanic.root", logging.INFO, "DEFAULT") in caplog.record_tuples