From 199d6ea99a30dffadaac58f77cc22d57e87c943c Mon Sep 17 00:00:00 2001 From: Adam Hopkins Date: Wed, 11 May 2022 09:23:04 +0300 Subject: [PATCH 1/3] Move verbosity filtering to logger --- sanic/app.py | 5 +++-- sanic/application/state.py | 5 ++++- sanic/asgi.py | 43 ++++++++++++++++++------------------ sanic/log.py | 18 +++++++++++++-- sanic/touchup/schemes/ode.py | 13 +++++------ tests/test_logging.py | 39 ++++++++++++++++++++++++++++++++ 6 files changed, 90 insertions(+), 33 deletions(-) diff --git a/sanic/app.py b/sanic/app.py index 4dbb1b2e5d..b87d1df6c7 100644 --- a/sanic/app.py +++ b/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 diff --git a/sanic/application/state.py b/sanic/application/state.py index 724ddcb5a8..5975c2a6f2 100644 --- a/sanic/application/state.py +++ b/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 diff --git a/sanic/asgi.py b/sanic/asgi.py index 2614016866..560abc66cc 100644 --- a/sanic/asgi.py +++ b/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: """ diff --git a/sanic/log.py b/sanic/log.py index 4b3b960c4d..e624c88234 100644 --- a/sanic/log.py +++ b/sanic/log.py @@ -59,23 +59,37 @@ class Colors(str, Enum): # no cov END = "\033[0m" - BLUE = "\033[01;34m" + RED = "\033[01;31m" GREEN = "\033[01;32m" YELLOW = "\033[01;33m" - RED = "\033[01;31m" + BLUE = "\033[01;34m" + PURPLE = "\033[01;35m" + + +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 """ diff --git a/sanic/touchup/schemes/ode.py b/sanic/touchup/schemes/ode.py index 7c6ed3d7b8..6303ed17cf 100644 --- a/sanic/touchup/schemes/ode.py +++ b/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 diff --git a/tests/test_logging.py b/tests/test_logging.py index c475b00bc2..274b407c54 100644 --- a/tests/test_logging.py +++ b/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 From e98a631a20163a945a30687e8ac8642f7d4775a8 Mon Sep 17 00:00:00 2001 From: Adam Hopkins Date: Wed, 11 May 2022 09:49:04 +0300 Subject: [PATCH 2/3] Fix verbosity test on ASGI --- tests/test_asgi.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/tests/test_asgi.py b/tests/test_asgi.py index 3687f5766f..58d1773c14 100644 --- a/tests/test_asgi.py +++ b/tests/test_asgi.py @@ -10,6 +10,7 @@ from sanic.application.state import Mode from sanic.asgi import MockTransport from sanic.exceptions import Forbidden, InvalidUsage, ServiceUnavailable +from sanic.log import VerbosityFilter from sanic.request import Request from sanic.response import json, text from sanic.server.websockets.connection import WebSocketConnection @@ -221,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() From 4d2afeda7733f44a712e37d5c2ffd1c51ebc58a7 Mon Sep 17 00:00:00 2001 From: Adam Hopkins Date: Wed, 11 May 2022 09:53:39 +0300 Subject: [PATCH 3/3] Add Sanic color --- sanic/log.py | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/sanic/log.py b/sanic/log.py index e624c88234..5911e8329d 100644 --- a/sanic/log.py +++ b/sanic/log.py @@ -59,11 +59,12 @@ class Colors(str, Enum): # no cov END = "\033[0m" - RED = "\033[01;31m" - GREEN = "\033[01;32m" - YELLOW = "\033[01;33m" BLUE = "\033[01;34m" + GREEN = "\033[01;32m" PURPLE = "\033[01;35m" + RED = "\033[01;31m" + SANIC = "\033[38;2;255;13;104m" + YELLOW = "\033[01;33m" class VerbosityFilter(logging.Filter):