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

@@ -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

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

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<path>.*?)\", line (?P<line_num>\d+), in (?P<location>.*)"
 )
+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,
+        }

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,

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

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)

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