Logging improvements (#2931)

* Add a separate logger for websockets and quiet down the noise. Also fix typo on server_logger. * Access log format changed to say chunked for size if not known. * Log unexpected disconnections to access log. Websocket timeout warning to sanic.websockets. * Websocket access logging added. * Avoid WS CLOSE logging if WS handshake was not completed yet; happens on server shutdownm with incoming connections; * Fix mixup * Keep peer stored for socket closing messages. * Remove log message timestamps to avoid duplicate time in system logs. Access log doesn't need level printed either. * Handler execution time on access log, colored and formatted log output. * Giving necessary context for error format messages * Strip control codes when not on terminal. * Add unique IDs for unix socket connections instead of UNKNOWN. * Add WS 1011 status * Fine tuning the ID * Experimenting with process names. Proof of concept, needs additional work ir not reversal. * More practical WS close statuses. * Avoid printing on logs any untrusted WS close reason as is. * Fix access logging to return 0 bytes for responses without body. * Typing fix * Simplify WebSocket status formatting. * Separate name and ident * Update logging to include debug and prod styles * Add logging module * Ruff formatting * Fix some tests * make pretty * Rename formatters * Fix ruff complaint * Add some documentation * Add some more documentation and docstrings * Fix type * Add colors to traceback * Add NO_COLOR config * Add some coloring tests * Account for new style error lines * Explicit color tests * Skip some coverage --------- Co-authored-by: L. Karkkainen <tronic@users.noreply.github.com> Co-authored-by: L. Kärkkäinen <98187+Tronic@users.noreply.github.com>
sanic-org · Apr 7, 2024 · bc1a3eb · bc1a3eb
1 parent b6a8f8e
commit bc1a3eb
Show file tree

Hide file tree

Showing 53 changed files with 1,013 additions and 417 deletions.
diff --git a/examples/exception_monitoring.py b/examples/exception_monitoring.py
@@ -7,6 +7,7 @@
 class' default handler, we can do anything including sending exceptions to
 an external service.
 """
+
 from sanic import Sanic
 from sanic.exceptions import SanicException
 from sanic.handlers import ErrorHandler

diff --git a/examples/pytest_xdist.py b/examples/pytest_xdist.py
@@ -8,6 +8,7 @@
 
     $ pytest examples/pytest_xdist.py -n 8  # 8 workers
 """
+
 import re
 
 import pytest

diff --git a/guide/config/en/sidebar.yaml b/guide/config/en/sidebar.yaml
@@ -257,7 +257,7 @@ root:
                   path: /api/sanic.compat.html
                 - label: sanic.helpers
                   path: /api/sanic.helpers.html
-                - label: sanic.log
-                  path: /api/sanic.log.html
+                - label: sanic.logging
+                  path: /api/sanic.logging.html
                 - label: sanic.utils
                   path: /api/sanic.utils.html
diff --git a/guide/content/en/guide/best-practices/logging.md b/guide/content/en/guide/best-practices/logging.md
@@ -2,8 +2,12 @@
 
 Sanic allows you to do different types of logging (access log, error log) on the requests based on the [Python logging API](https://docs.python.org/3/howto/logging.html). You should have some basic knowledge on Python logging if you want to create a new configuration.
 
+But, don't worry, out of the box Sanic ships with some sensible logging defaults. Out of the box it uses an `AutoFormatter` that will format the logs depending upon whether you are in debug mode or not. We will show you how to force this later on.
+
 ## Quick Start
 
+Let's start by looking at what logging might look like in local development. For this, we will use the default logging configuration that Sanic provides and make sure to run Sanic in development mode.
+
 .. column::
 
     A simple example using default settings would be like this:
@@ -21,77 +25,173 @@ Sanic allows you to do different types of logging (access log, error log) on the
     async def test(request):
         logger.info('Here is your log')
         return text('Hello World!')
-
-    if __name__ == "__main__":
-      app.run(debug=True, access_log=True)
     ```
 
+.. column::
+
+    Because we are specifically trying to look at the development logs, we will make sure to run Sanic in development mode.
+
+.. column::
+
+    ```sh
+    sanic path.to.server:app --dev
+    ```    
+
+
 After the server is running, you should see logs like this.
-```text
-[2021-01-04 15:26:26 +0200] [1929659] [INFO] Goin' Fast @ http://127.0.0.1:8000
-[2021-01-04 15:26:26 +0200] [1929659] [INFO] Starting worker [1929659]
-```
+
+![Sanic Logging Start](/assets/images/logging-debug-start.png)
 
 You can send a request to server and it will print the log messages.
-```text
-[2021-01-04 15:26:28 +0200] [1929659] [INFO] Here is your log
-[2021-01-04 15:26:28 +0200] - (sanic.access)[INFO][127.0.0.1:44228]: GET http://localhost:8000/  200 -1
-```
 
-## Changing Sanic loggers
+![Sanic Logging Access](/assets/images/logging-debug-access.png)
 
-To use your own logging config, simply use `logging.config.dictConfig`, or pass `log_config` when you initialize Sanic app.
+Some important points to note:
 
-```python
-app = Sanic('logging_example', log_config=LOGGING_CONFIG)
+- The default log level in **production** mode is `INFO`.
+- The default log level in **debug** mode is `DEBUG`.
+- When in **debug** mode, the log messages will not have a timestamp (except on access logs).
+- Sanic will try to colorize the logs if the terminal supports it. If you are running in Docker with docker-compose, you may need to set `tty: true` in your `docker-compose.yml` file to see the colors.
 
-if __name__ == "__main__":
-  app.run(access_log=False)
-```
+## Sanic's loggers
 
+Out of the box, Sanic ships with five loggers:
 
-.. tip:: FYI
+| **Logger Name**   | **Use Case**                  |
+|-------------------|-------------------------------|
+| `sanic.root`      | Used to log internal messages. |
+| `sanic.error`     | Used to log error logs.       |
+| `sanic.access`    | Used to log access logs.      |
+| `sanic.server`    | Used to log server logs.      |
+| `sanic.websockets`| Used to log websocket logs.   |
 
-    Logging in Python is a relatively cheap operation. However, if you are serving a high number of requests and performance is a concern, all of that time logging out access logs adds up and becomes quite expensive.  
+.. column::
 
-    This is a good opportunity to place Sanic behind a proxy (like nginx) and to do your access logging there. You will see a *significant* increase in overall performance by disabling the `access_log`.  
+    If you want to use these loggers yourself, you can import them from `sanic.log`.
+
+.. column::
 
-    For optimal production performance, it is advised to run Sanic with `debug` and `access_log` disabled: `app.run(debug=False, access_log=False)`
+    ```python
+    from sanic.log import logger, error_logger, access_logger, server_logger, websockets_logger
+
+    logger.info('This is a root logger message')
+    ```
+
+.. warning::
+
+    Feel free to use the root logger and the error logger yourself. But, you probably don't want to use the access logger, server logger, or websockets logger directly. These are used internally by Sanic and are configured to log in a specific way. If you want to change the way these loggers log, you should change the logging configuration.
+
+## Default logging configuration
 
+Sanic ships with a default logging configuration that is used when you do not provide your own. This configuration is stored in `sanic.log.LOGGING_CONFIG_DEFAULTS`.
 
-## Configuration
+```python
+{
+    'version': 1,
+    'disable_existing_loggers': False,
+    'loggers': {
+        'sanic.root': {'level': 'INFO', 'handlers': ['console']},
+        'sanic.error': {
+            'level': 'INFO',
+            'handlers': ['error_console'],
+            'propagate': True,
+            'qualname': 'sanic.error'
+        },
+        'sanic.access': {
+            'level': 'INFO',
+            'handlers': ['access_console'],
+            'propagate': True,
+            'qualname': 'sanic.access'
+        },
+        'sanic.server': {
+            'level': 'INFO',
+            'handlers': ['console'],
+            'propagate': True,
+            'qualname': 'sanic.server'
+        },
+        'sanic.websockets': {
+            'level': 'INFO',
+            'handlers': ['console'],
+            'propagate': True,
+            'qualname': 'sanic.websockets'
+        }
+    },
+    'handlers': {
+        'console': {
+            'class': 'logging.StreamHandler',
+            'formatter': 'generic',
+            'stream': sys.stdout
+        },
+        'error_console': {
+            'class': 'logging.StreamHandler',
+            'formatter': 'generic',
+            'stream': sys.stderr
+        },
+        'access_console': {
+            'class': 'logging.StreamHandler',
+            'formatter': 'access',
+            'stream': sys.stdout
+        }
+    },
+    'formatters': {
+        'generic': {'class': 'sanic.logging.formatter.AutoFormatter'},
+        'access': {'class': 'sanic.logging.formatter.AutoAccessFormatter'}
+    }
+}
+```
 
-Sanic's default logging configuration is: `sanic.log.LOGGING_CONFIG_DEFAULTS`.
+## Changing Sanic loggers
 
 .. column::
 
-    There are three loggers used in sanic, and must be defined if you want to create your own logging configuration:
+    To use your own logging config, simply use `logging.config.dictConfig`, or pass `log_config` when you initialize Sanic app.
 
-    | **Logger Name** | **Use Case**                  |
-    |-----------------|-------------------------------|
-    | `sanic.root`    | Used to log internal messages. |
-    | `sanic.error`   | Used to log error logs.       |
-    | `sanic.access`  | Used to log access logs.      |
+.. column::
+
+    ```python
+    app = Sanic('logging_example', log_config=LOGGING_CONFIG)
+
+    if __name__ == "__main__":
+        app.run(access_log=False)
+    ```
 
 .. column::
 
+    But, what if you do not want to control the logging completely, just change the formatter for example? Here, we will import the default logging config and modify only the parts that we want to force (for example) to use the `ProdFormatter` all of the time.
+
+.. column::
 
+    ```python
+    from sanic.log import LOGGING_CONFIG_DEFAULTS
+
+    LOGGING_CONFIG_DEFAULTS['formatters']['generic']['class'] = 'sanic.logging.formatter.ProdFormatter'
+    LOGGING_CONFIG_DEFAULTS['formatters']['access']['class'] = 'sanic.logging.formatter.ProdAccessFormatter'
+
+    app = Sanic('logging_example', log_config=LOGGING_CONFIG_DEFAULTS)
+    ```
 
-### Log format
 
-In addition to default parameters provided by Python (`asctime`, `levelname`, `message`), Sanic provides additional parameters for access logger with.
+.. tip:: FYI
+
+    Logging in Python is a relatively cheap operation. However, if you are serving a high number of requests and performance is a concern, all of that time logging out access logs adds up and becomes quite expensive.  
+
+    This is a good opportunity to place Sanic behind a proxy (like nginx) and to do your access logging there. You will see a *significant* increase in overall performance by disabling the `access_log`.  
+
+    For optimal production performance, it is advised to run Sanic with `debug` and `access_log` disabled: `app.run(debug=False, access_log=False)`
+
+
+## Access logger additional parameters
+
+Sanic provides additional parameters to the access logger.
 
 | Log Context Parameter | Parameter Value                       | Datatype |
 |-----------------------|---------------------------------------|----------|
 | `host`                | `request.ip`                          | `str`    |
 | `request`             | `request.method + " " + request.url`  | `str`    |
 | `status`              | `response`                            | `int`    |
 | `byte`                | `len(response.body)`                  | `int`    |
+| `duration`            | <calculated>                          | `float`  |
 
+## Legacy logging
 
-
-The default access log format is:
-
-```text
-%(asctime)s - (%(name)s)[%(levelname)s][%(host)s]: %(request)s %(message)s %(status)d %(byte)d
-```
+Many logging changes were introduced in Sanic 24.3. The main changes were related to logging formats. If you prefer the legacy logging format, you can use the `sanic.logging.formatter.LegacyFormatter` and `sanic.logging.formatter.LegacyAccessFormatter` formatters.
diff --git a/guide/public/assets/images/logging-debug-access.png b/guide/public/assets/images/logging-debug-access.png
diff --git a/guide/public/assets/images/logging-debug-start.png b/guide/public/assets/images/logging-debug-start.png
diff --git a/guide/server.py b/guide/server.py
@@ -6,6 +6,7 @@
 - Sanic
 - html5tagger
 - HTMX"""
+
 from pathlib import Path
 
 from webapp.worker.factory import create_app

diff --git a/pyproject.toml b/pyproject.toml
@@ -27,7 +27,7 @@ indent-style = "space"
 skip-magic-trailing-comma = false
 line-ending = "auto"
 
-[tool.ruff.isort]
+[tool.ruff.lint.isort]
 known-first-party = ["sanic"]
 known-third-party = ["pytest"]
 lines-after-imports = 2

diff --git a/sanic/__version__.py b/sanic/__version__.py
@@ -1 +1 @@
-__version__ = "23.12.0"
+__version__ = "24.3.0.dev"
diff --git a/sanic/app.py b/sanic/app.py
@@ -72,6 +72,7 @@
 from sanic.helpers import Default, _default
 from sanic.http import Stage
 from sanic.log import LOGGING_CONFIG_DEFAULTS, error_logger, logger
+from sanic.logging.setup import setup_logging
 from sanic.middleware import Middleware, MiddlewareLocation
 from sanic.mixins.listeners import ListenerEvent
 from sanic.mixins.startup import StartupMixin
@@ -1937,6 +1938,7 @@ async def __call__(self, scope, receive, send):
         details: https://asgi.readthedocs.io/en/latest
         """
         if scope["type"] == "lifespan":
+            setup_logging(self.state.is_debug, self.config.NO_COLOR)
             self.asgi = True
             self.motd("")
             self._asgi_lifespan = Lifespan(self, scope, receive, send)

diff --git a/sanic/config.py b/sanic/config.py
@@ -58,6 +58,7 @@
     "LOCALHOST": "localhost",
     "MOTD": True,
     "MOTD_DISPLAY": {},
+    "NO_COLOR": False,
     "NOISY_EXCEPTIONS": False,
     "PROXIES_COUNT": None,
     "REAL_IP_HEADER": None,
@@ -116,6 +117,7 @@ class Config(dict, metaclass=DescriptorMeta):
     LOCALHOST: str
     MOTD: bool
     MOTD_DISPLAY: Dict[str, str]
+    NO_COLOR: bool
     NOISY_EXCEPTIONS: bool
     PROXIES_COUNT: Optional[int]
     REAL_IP_HEADER: Optional[str]

diff --git a/sanic/errorpages.py b/sanic/errorpages.py
@@ -392,8 +392,14 @@ def guess_mime(req: Request, fallback: str) -> str:
         format = CONFIG_BY_MIME[m.mime]
         source = formats[format]
         logger.debug(
-            f"The client accepts {m.header}, using '{format}' from {source}"
+            "Error Page: The client accepts %s, using '%s' from %s",
+            m.header,
+            format,
+            source,
         )
     else:
-        logger.debug(f"No format found, the client accepts {req.accept!r}")
+        logger.debug(
+            "Error Page: No format found, the client accepts %s",
+            repr(req.accept),
+        )
     return m.mime
diff --git a/sanic/http/http1.py b/sanic/http/http1.py
@@ -8,6 +8,7 @@
     from sanic.response import BaseHTTPResponse
 
 from asyncio import CancelledError, sleep
+from time import perf_counter
 
 from sanic.compat import Header
 from sanic.exceptions import (
@@ -70,6 +71,7 @@ class Http(Stream, metaclass=TouchUpMeta):
         "response_size",
         "response_bytes_left",
         "upgrade_websocket",
+        "perft0",
     ]
 
     def __init__(self, protocol):
@@ -94,6 +96,7 @@ def init_for_request(self):
         self.response: BaseHTTPResponse = None
         self.upgrade_websocket = False
         self.url = None
+        self.perft0 = None
 
     def __bool__(self):
         """Test if request handling is in progress"""
@@ -115,6 +118,7 @@ async def http1(self):
                 await self.http1_request_header()
 
                 self.stage = Stage.HANDLER
+                self.perft0 = perf_counter()
                 self.request.conn_info = self.protocol.conn_info
                 await self.protocol.request_handler(self.request)
 
@@ -459,16 +463,20 @@ def log_response(self) -> None:
         req, res = self.request, self.response
         extra = {
             "status": getattr(res, "status", 0),
-            "byte": getattr(
-                self, "response_bytes_left", getattr(self, "response_size", -1)
-            ),
-            "host": "UNKNOWN",
+            "byte": res.headers.get("content-length", 0)
+            if res.headers.get("transfer-encoding") != "chunked"
+            else "chunked",
+            "host": f"{id(self.protocol.transport):X}"[-5:-1] + "unx",
             "request": "nil",
+            "duration": (
+                f" {1000 * (perf_counter() - self.perft0):.1f}ms"
+                if self.perft0 is not None
+                else ""
+            ),
         }
-        if req is not None:
-            if req.remote_addr or req.ip:
-                extra["host"] = f"{req.remote_addr or req.ip}:{req.port}"
-            extra["request"] = f"{req.method} {req.url}"
+        if ip := req.client_ip:
+            extra["host"] = f"{ip}:{req.port}"
+        extra["request"] = f"{req.method} {req.url}"
         access_logger.info("", extra=extra)
 
     # Request methods