From e3d59c121dd537168bc9d66f18194856f2630866 Mon Sep 17 00:00:00 2001 From: Adam Hopkins Date: Sun, 23 Jun 2024 16:36:58 +0300 Subject: [PATCH] Add logging of extras and a JSONFormatter (#2958) * Add logging of extras and a JSONFormatter * Make pretty * Fix config typing * Reset environ --- sanic/config.py | 2 + sanic/helpers.py | 12 +++ sanic/logging/formatter.py | 153 ++++++++++++++++++++++++++++++++++++- sanic/logging/setup.py | 16 +++- sanic/response/types.py | 19 +---- sanic/worker/serve.py | 4 +- tests/conftest.py | 5 ++ 7 files changed, 188 insertions(+), 23 deletions(-) diff --git a/sanic/config.py b/sanic/config.py index c12eef8148..ddaf47adcb 100644 --- a/sanic/config.py +++ b/sanic/config.py @@ -56,6 +56,7 @@ "LOCAL_TLS_KEY": _default, "LOCAL_TLS_CERT": _default, "LOCALHOST": "localhost", + "LOG_EXTRA": _default, "MOTD": True, "MOTD_DISPLAY": {}, "NO_COLOR": False, @@ -115,6 +116,7 @@ class Config(dict, metaclass=DescriptorMeta): LOCAL_TLS_KEY: Union[Path, str, Default] LOCAL_TLS_CERT: Union[Path, str, Default] LOCALHOST: str + LOG_EXTRA: Union[Default, bool] MOTD: bool MOTD_DISPLAY: Dict[str, str] NO_COLOR: bool diff --git a/sanic/helpers.py b/sanic/helpers.py index fbdac97f49..b0c8f224b1 100644 --- a/sanic/helpers.py +++ b/sanic/helpers.py @@ -2,11 +2,23 @@ import sys +from functools import partial from importlib import import_module from inspect import ismodule from typing import Dict +try: + from ujson import dumps as ujson_dumps + + json_dumps = partial(ujson_dumps, escape_forward_slashes=False) +except ImportError: + # This is done in order to ensure that the JSON response is + # kept consistent across both ujson and inbuilt json usage. + from json import dumps + + json_dumps = partial(dumps, separators=(",", ":")) + STATUS_CODES: Dict[int, bytes] = { 100: b"Continue", 101: b"Switching Protocols", diff --git a/sanic/logging/formatter.py b/sanic/logging/formatter.py index f3e685f21c..60124e5f08 100644 --- a/sanic/logging/formatter.py +++ b/sanic/logging/formatter.py @@ -4,7 +4,7 @@ import os import re -from sanic.helpers import is_atty +from sanic.helpers import is_atty, json_dumps from sanic.logging.color import LEVEL_COLORS from sanic.logging.color import Colors as c @@ -17,6 +17,14 @@ FILE_LINE_RE = re.compile( r"File \"(?P.*?)\", line (?P\d+), in (?P.*)" ) +DEFAULT_FIELDS = set( + logging.LogRecord("", 0, "", 0, "", (), None).__dict__.keys() +) | { + "ident", + "message", + "asctime", + "right", +} class AutoFormatter(logging.Formatter): @@ -31,6 +39,7 @@ class AutoFormatter(logging.Formatter): SETUP = False ATTY = is_atty() NO_COLOR = os.environ.get("SANIC_NO_COLOR", "false").lower() == "true" + LOG_EXTRA = os.environ.get("SANIC_LOG_EXTRA", "true").lower() == "true" IDENT = os.environ.get("SANIC_WORKER_IDENTIFIER", "Main ") or "Main " DATE_FORMAT = "%Y-%m-%d %H:%M:%S %z" IDENT_LIMIT = 5 @@ -57,7 +66,10 @@ def __init__(self, *args) -> None: def format(self, record: logging.LogRecord) -> str: record.ident = self.IDENT self._set_levelname(record) - return super().format(record) + output = super().format(record) + if self.LOG_EXTRA: + output += self._log_extra(record) + return output def _set_levelname(self, record: logging.LogRecord) -> None: if ( @@ -76,6 +88,34 @@ def _make_format(self) -> str: return CONTROL_RE.sub("", fmt) return fmt + def _log_extra(self, record: logging.LogRecord, indent: int = 0) -> str: + extra_lines = [""] + + for key, value in record.__dict__.items(): + if key not in DEFAULT_FIELDS: + extra_lines.append(self._format_key_value(key, value, indent)) + + return "\n".join(extra_lines) + + def _format_key_value(self, key, value, indent): + indentation = " " * indent + template = ( + f"{indentation} {{c.YELLOW}}{{key}}{{c.END}}={{value}}" + if self.ATTY and not self.NO_COLOR + else f"{indentation}{{key}}={{value}}" + ) + if isinstance(value, dict): + nested_lines = [template.format(c=c, key=key, value="")] + for nested_key, nested_value in value.items(): + nested_lines.append( + self._format_key_value( + nested_key, nested_value, indent + 2 + ) + ) + return "\n".join(nested_lines) + else: + return template.format(c=c, key=key, value=value) + class DebugFormatter(AutoFormatter): """ @@ -222,6 +262,7 @@ class DebugAccessFormatter(AutoAccessFormatter): IDENT_LIMIT = 5 MESSAGE_START = 23 DATE_FORMAT = "%H:%M:%S" + LOG_EXTRA = False class ProdAccessFormatter(AutoAccessFormatter): @@ -236,3 +277,111 @@ class ProdAccessFormatter(AutoAccessFormatter): f"%(request)s{c.END} " f"%(right)s%(status)s %(byte)s {c.GREY}%(duration)s{c.END}" ) + LOG_EXTRA = False + + +class JSONFormatter(AutoFormatter): + """ + The JSONFormatter is used to output logs in JSON format. + + This is useful for logging to a file or to a log aggregator that + understands JSON. It will output all the fields from the LogRecord + as well as the extra fields that are passed in. + + You can use it as follows: + + .. code-block:: python + + from sanic.log import LOGGING_CONFIG_DEFAULTS + + LOGGING_CONFIG_DEFAULTS["formatters"] = { + "generic": { + "class": "sanic.logging.formatter.JSONFormatter" + }, + "access": { + "class": "sanic.logging.formatter.JSONFormatter" + }, + } + """ + + ATTY = False + NO_COLOR = True + FIELDS = [ + "name", + "levelno", + "pathname", + "module", + "filename", + "lineno", + ] + + dumps = json_dumps + + def format(self, record: logging.LogRecord) -> str: + return self.format_dict(self.to_dict(record)) + + def to_dict(self, record: logging.LogRecord) -> dict: + base = {field: getattr(record, field, None) for field in self.FIELDS} + extra = { + key: value + for key, value in record.__dict__.items() + if key not in DEFAULT_FIELDS + } + info = {} + if record.exc_info: + info["exc_info"] = self.formatException(record.exc_info) + if record.stack_info: + info["stack_info"] = self.formatStack(record.stack_info) + return { + "timestamp": self.formatTime(record, self.datefmt), + "level": record.levelname, + "message": record.getMessage(), + **base, + **info, + **extra, + } + + def format_dict(self, record: dict) -> str: + return self.dumps(record) + + +class JSONAccessFormatter(JSONFormatter): + """ + The JSONAccessFormatter is used to output access logs in JSON format. + + This is useful for logging to a file or to a log aggregator that + understands JSON. It will output all the fields from the LogRecord + as well as the extra fields that are passed in. + + You can use it as follows: + + .. code-block:: python + + from sanic.log import LOGGING_CONFIG_DEFAULTS + + LOGGING_CONFIG_DEFAULTS["formatters"] = { + "generic": { + "class": "sanic.logging.formatter.JSONFormatter" + }, + "access": { + "class": "sanic.logging.formatter.JSONAccessFormatter" + }, + } + """ + + FIELDS = [ + "host", + "request", + "status", + "byte", + "duration", + ] + + def to_dict(self, record: logging.LogRecord) -> dict: + base = {field: getattr(record, field, None) for field in self.FIELDS} + return { + "timestamp": self.formatTime(record, self.datefmt), + "level": record.levelname, + "message": record.getMessage(), + **base, + } diff --git a/sanic/logging/setup.py b/sanic/logging/setup.py index 19712412ec..810e85c5b2 100644 --- a/sanic/logging/setup.py +++ b/sanic/logging/setup.py @@ -1,8 +1,9 @@ import logging import os -from typing import Type +from typing import Type, Union +from sanic.helpers import Default, _default from sanic.log import ( access_logger, error_logger, @@ -20,14 +21,25 @@ ) -def setup_logging(debug: bool, no_color: bool = False) -> None: +def setup_logging( + debug: bool, + no_color: bool = False, + log_extra: Union[bool, Default] = _default, +) -> None: if AutoFormatter.SETUP: return + if isinstance(log_extra, Default): + log_extra = debug + os.environ["SANIC_LOG_EXTRA"] = str(log_extra) + AutoFormatter.LOG_EXTRA = log_extra + if no_color: os.environ["SANIC_NO_COLOR"] = str(no_color) AutoFormatter.NO_COLOR = no_color + AutoFormatter.SETUP = True + for lggr in (logger, server_logger, error_logger, websockets_logger): _auto_format( lggr, diff --git a/sanic/response/types.py b/sanic/response/types.py index 8dbde38e30..12f48bc70b 100644 --- a/sanic/response/types.py +++ b/sanic/response/types.py @@ -1,7 +1,6 @@ from __future__ import annotations from datetime import datetime -from functools import partial from typing import ( TYPE_CHECKING, Any, @@ -20,11 +19,7 @@ from sanic.cookies import CookieJar from sanic.cookies.response import Cookie, SameSite from sanic.exceptions import SanicException, ServerError -from sanic.helpers import ( - Default, - _default, - has_message_body, -) +from sanic.helpers import Default, _default, has_message_body, json_dumps from sanic.http import Http @@ -36,18 +31,6 @@ Request = TypeVar("Request") -try: - from ujson import dumps as ujson_dumps - - json_dumps = partial(ujson_dumps, escape_forward_slashes=False) -except ImportError: - # This is done in order to ensure that the JSON response is - # kept consistent across both ujson and inbuilt json usage. - from json import dumps - - json_dumps = partial(dumps, separators=(",", ":")) - - class BaseHTTPResponse: """The base class for all HTTP Responses""" diff --git a/sanic/worker/serve.py b/sanic/worker/serve.py index 2239631f94..f9e6ec4312 100644 --- a/sanic/worker/serve.py +++ b/sanic/worker/serve.py @@ -59,7 +59,9 @@ def worker_serve( app.refresh(passthru) app.setup_loop() - setup_logging(app.state.is_debug, app.config.NO_COLOR) + setup_logging( + app.state.is_debug, app.config.NO_COLOR, app.config.LOG_EXTRA + ) loop = asyncio.new_event_loop() asyncio.set_event_loop(loop) diff --git a/tests/conftest.py b/tests/conftest.py index 50ecd12850..e057d3d239 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -21,6 +21,7 @@ from sanic import Sanic from sanic.constants import HTTP_METHODS +from sanic.logging.formatter import AutoFormatter from sanic.router import Router from sanic.touchup.service import TouchUp @@ -167,6 +168,10 @@ def app(request): for target, method_name in TouchUp._registry: setattr(target, method_name, CACHE[method_name]) Sanic._app_registry.clear() + AutoFormatter.SETUP = False + AutoFormatter.LOG_EXTRA = False + os.environ.pop("SANIC_LOG_EXTRA", None) + os.environ.pop("SANIC_NO_COLOR", None) @pytest.fixture(scope="function")