Merge pull request #1442 from Amanit/feature/gunicorn-logging

add an option to change access_log using gunicorn

docs/sanic/deploying.md

@@ -15,6 +15,7 @@ keyword arguments:
 - `protocol` *(default `HttpProtocol`)*: Subclass
   of
   [asyncio.protocol](https://docs.python.org/3/library/asyncio-protocol.html#protocol-classes).
+- `access_log` *(default `True`)*: Enables log on handling requests (significantly slows server).
 
 ## Workers
 
@@ -63,6 +64,26 @@ of the memory leak.
 
 See the [Gunicorn Docs](http://docs.gunicorn.org/en/latest/settings.html#max-requests) for more information.
 
+## Disable debug logging
+
+To improve the performance add `debug=False` and `access_log=False` in the `run` arguments.
+
+```python
+app.run(host='0.0.0.0', port=1337, workers=4, debug=False, access_log=False)
+```
+
+Running via Gunicorn you can set Environment variable `SANIC_ACCESS_LOG="False"`
+
+```
+env SANIC_ACCESS_LOG="False" gunicorn myapp:app --bind 0.0.0.0:1337 --worker-class sanic.worker.GunicornWorker --log-level warning
+```
+
+Or you can rewrite app config directly
+
+```python
+app.config.ACCESS_LOG = False
+```
+
 ## Asynchronous support
 This is suitable if you *need* to share the sanic process with other applications, in particular the `loop`.
 However be advised that this method does not support using multiple processes, and is not the preferred way

sanic/app.py

@@ -4,12 +4,14 @@ import os
 import re
 import warnings
 
-from asyncio import CancelledError, ensure_future, get_event_loop
+from asyncio import CancelledError, Protocol, ensure_future, get_event_loop
 from collections import defaultdict, deque
 from functools import partial
 from inspect import getmodulename, isawaitable, signature, stack
-from ssl import Purpose, create_default_context
+from socket import socket
+from ssl import Purpose, SSLContext, create_default_context
 from traceback import format_exc
+from typing import Any, Optional, Type, Union
 from urllib.parse import urlencode, urlunparse
 
 from sanic import reloader_helpers
@@ -967,34 +969,47 @@ class Sanic:
 
     def run(
         self,
-        host=None,
+        host: Optional[str] = None,
-        port=None,
+        port: Optional[int] = None,
-        debug=False,
+        debug: bool = False,
-        ssl=None,
+        ssl: Union[dict, SSLContext, None] = None,
-        sock=None,
+        sock: Optional[socket] = None,
-        workers=1,
+        workers: int = 1,
-        protocol=None,
+        protocol: Type[Protocol] = None,
-        backlog=100,
+        backlog: int = 100,
-        stop_event=None,
+        stop_event: Any = None,
-        register_sys_signals=True,
+        register_sys_signals: bool = True,
-        access_log=True,
+        access_log: Optional[bool] = None,
-        **kwargs
+        **kwargs: Any
-    ):
+    ) -> None:
         """Run the HTTP Server and listen until keyboard interrupt or term
         signal. On termination, drain connections before closing.
 
         :param host: Address to host on
+        :type host: str
         :param port: Port to host on
+        :type port: int
         :param debug: Enables debug output (slows server)
+        :type debug: bool
         :param ssl: SSLContext, or location of certificate and key
             for SSL encryption of worker(s)
+        :type ssl:SSLContext or dict
         :param sock: Socket for the server to accept connections from
+        :type sock: socket
         :param workers: Number of processes received before it is respected
+        :type workers: int
+        :param protocol: Subclass of asyncio Protocol class
+        :type protocol: type[Protocol]
         :param backlog: a number of unaccepted connections that the system
             will allow before refusing new connections
-        :param stop_event: event to be triggered before stopping the app
+        :type backlog: int
+        :param stop_event: event to be triggered
+            before stopping the app - deprecated
+        :type stop_event: None
         :param register_sys_signals: Register SIG* events
-        :param protocol: Subclass of asyncio protocol class
+        :type register_sys_signals: bool
+        :param access_log: Enables writing access logs (slows server)
+        :type access_log: bool
         :return: Nothing
         """
         if "loop" in kwargs:
@@ -1027,8 +1042,10 @@ class Sanic:
                 "stop_event will be removed from future versions.",
                 DeprecationWarning,
             )
-        # compatibility old access_log params
+        # if access_log is passed explicitly change config.ACCESS_LOG
+        if access_log is not None:
             self.config.ACCESS_LOG = access_log
+
         server_settings = self._helper(
             host=host,
             port=port,
@@ -1078,16 +1095,16 @@ class Sanic:
 
     async def create_server(
         self,
-        host=None,
+        host: Optional[str] = None,
-        port=None,
+        port: Optional[int] = None,
-        debug=False,
+        debug: bool = False,
-        ssl=None,
+        ssl: Union[dict, SSLContext, None] = None,
-        sock=None,
+        sock: Optional[socket] = None,
-        protocol=None,
+        protocol: Type[Protocol] = None,
-        backlog=100,
+        backlog: int = 100,
-        stop_event=None,
+        stop_event: Any = None,
-        access_log=True,
+        access_log: Optional[bool] = None,
-    ):
+    ) -> None:
         """
         Asynchronous version of :func:`run`.
 
@@ -1098,6 +1115,29 @@ class Sanic:
         .. note::
             This does not support multiprocessing and is not the preferred
             way to run a :class:`Sanic` application.
+
+        :param host: Address to host on
+        :type host: str
+        :param port: Port to host on
+        :type port: int
+        :param debug: Enables debug output (slows server)
+        :type debug: bool
+        :param ssl: SSLContext, or location of certificate and key
+            for SSL encryption of worker(s)
+        :type ssl:SSLContext or dict
+        :param sock: Socket for the server to accept connections from
+        :type sock: socket
+        :param protocol: Subclass of asyncio Protocol class
+        :type protocol: type[Protocol]
+        :param backlog: a number of unaccepted connections that the system
+            will allow before refusing new connections
+        :type backlog: int
+        :param stop_event: event to be triggered
+            before stopping the app - deprecated
+        :type stop_event: None
+        :param access_log: Enables writing access logs (slows server)
+        :type access_log: bool
+        :return: Nothing
         """
 
         if sock is None:
@@ -1114,8 +1154,10 @@ class Sanic:
                 "stop_event will be removed from future versions.",
                 DeprecationWarning,
             )
-        # compatibility old access_log params
+        # if access_log is passed explicitly change config.ACCESS_LOG
+        if access_log is not None:
             self.config.ACCESS_LOG = access_log
+
         server_settings = self._helper(
             host=host,
             port=port,

sanic/config.py

@@ -1,6 +1,8 @@
 import os
 import types
 
+from distutils.util import strtobool
+
 from sanic.exceptions import PyFileError
 
 
@@ -12,23 +14,31 @@ BASE_LOGO = """
 
 """
 
+DEFAULT_CONFIG = {
+    "REQUEST_MAX_SIZE": 100000000,  # 100 megabytes
+    "REQUEST_BUFFER_QUEUE_SIZE": 100,
+    "REQUEST_TIMEOUT": 60,  # 60 seconds
+    "RESPONSE_TIMEOUT": 60,  # 60 seconds
+    "KEEP_ALIVE": True,
+    "KEEP_ALIVE_TIMEOUT": 5,  # 5 seconds
+    "WEBSOCKET_MAX_SIZE": 2 ** 20,  # 1 megabytes
+    "WEBSOCKET_MAX_QUEUE": 32,
+    "WEBSOCKET_READ_LIMIT": 2 ** 16,
+    "WEBSOCKET_WRITE_LIMIT": 2 ** 16,
+    "GRACEFUL_SHUTDOWN_TIMEOUT": 15.0,  # 15 sec
+    "ACCESS_LOG": True,
+}
+
 
 class Config(dict):
-    def __init__(self, defaults=None, load_env=True, keep_alive=True):
+    def __init__(self, defaults=None, load_env=True, keep_alive=None):
-        super().__init__(defaults or {})
+        defaults = defaults or {}
+        super().__init__({**DEFAULT_CONFIG, **defaults})
+
         self.LOGO = BASE_LOGO
-        self.REQUEST_MAX_SIZE = 100000000  # 100 megabytes
+
-        self.REQUEST_BUFFER_QUEUE_SIZE = 100
+        if keep_alive is not None:
-        self.REQUEST_TIMEOUT = 60  # 60 seconds
-        self.RESPONSE_TIMEOUT = 60  # 60 seconds
             self.KEEP_ALIVE = keep_alive
-        self.KEEP_ALIVE_TIMEOUT = 5  # 5 seconds
-        self.WEBSOCKET_MAX_SIZE = 2 ** 20  # 1 megabytes
-        self.WEBSOCKET_MAX_QUEUE = 32
-        self.WEBSOCKET_READ_LIMIT = 2 ** 16
-        self.WEBSOCKET_WRITE_LIMIT = 2 ** 16
-        self.GRACEFUL_SHUTDOWN_TIMEOUT = 15.0  # 15 sec
-        self.ACCESS_LOG = True
 
         if load_env:
             prefix = SANIC_PREFIX if load_env is True else load_env
@@ -115,5 +125,8 @@ class Config(dict):
                 except ValueError:
                     try:
                         self[config_key] = float(v)
+                    except ValueError:
+                        try:
+                            self[config_key] = bool(strtobool(v))
                         except ValueError:
                             self[config_key] = v

sanic/worker.py

@@ -57,6 +57,7 @@ class GunicornWorker(base.Worker):
             if self.app.callable.websocket_enabled
             else self.http_protocol
         )
+
         self._server_settings = self.app.callable._helper(
             loop=self.loop,
             debug=is_debug,

tests/test_config.py

@@ -6,6 +6,7 @@ from textwrap import dedent
 import pytest
 
 from sanic import Sanic
+from sanic.config import Config, DEFAULT_CONFIG
 from sanic.exceptions import PyFileError
 
 
@@ -34,6 +35,13 @@ def test_auto_load_env():
     del environ["SANIC_TEST_ANSWER"]
 
 
+def test_auto_load_bool_env():
+    environ["SANIC_TEST_ANSWER"] = "True"
+    app = Sanic()
+    assert app.config.TEST_ANSWER == True
+    del environ["SANIC_TEST_ANSWER"]
+
+
 def test_dont_load_env():
     environ["SANIC_TEST_ANSWER"] = "42"
     app = Sanic(load_env=False)
@@ -139,3 +147,107 @@ def test_missing_config(app):
     with pytest.raises(AttributeError) as e:
         app.config.NON_EXISTENT
         assert str(e.value) == ("Config has no 'NON_EXISTENT'")
+
+
+def test_config_defaults():
+    """
+    load DEFAULT_CONFIG
+    """
+    conf = Config()
+    for key, value in DEFAULT_CONFIG.items():
+        assert getattr(conf, key) == value
+
+
+def test_config_custom_defaults():
+    """
+    we should have all the variables from defaults rewriting them with custom defaults passed in
+    Config
+    """
+    custom_defaults = {
+        "REQUEST_MAX_SIZE": 1,
+        "KEEP_ALIVE": False,
+        "ACCESS_LOG": False
+    }
+    conf = Config(defaults=custom_defaults)
+    for key, value in DEFAULT_CONFIG.items():
+        if key in custom_defaults.keys():
+            value = custom_defaults[key]
+        assert getattr(conf, key) == value
+
+
+def test_config_custom_defaults_with_env():
+    """
+    test that environment variables has higher priority than DEFAULT_CONFIG and passed defaults dict
+    """
+    custom_defaults = {
+        "REQUEST_MAX_SIZE123": 1,
+        "KEEP_ALIVE123": False,
+        "ACCESS_LOG123": False
+    }
+
+    environ_defaults = {
+        "SANIC_REQUEST_MAX_SIZE123": "2",
+        "SANIC_KEEP_ALIVE123": "True",
+        "SANIC_ACCESS_LOG123": "False"
+    }
+
+    for key, value in environ_defaults.items():
+        environ[key] = value
+
+    conf = Config(defaults=custom_defaults)
+    for key, value in DEFAULT_CONFIG.items():
+        if "SANIC_" + key in environ_defaults.keys():
+            value = environ_defaults["SANIC_" + key]
+            try:
+                value = int(value)
+            except ValueError:
+                if value in ['True', 'False']:
+                    value = value == 'True'
+
+        assert getattr(conf, key) == value
+
+    for key, value in environ_defaults.items():
+        del environ[key]
+
+
+def test_config_access_log_passing_in_run(app):
+    assert app.config.ACCESS_LOG == True
+
+    @app.listener('after_server_start')
+    async def _request(sanic, loop):
+        app.stop()
+
+    app.run(port=1340, access_log=False)
+    assert app.config.ACCESS_LOG == False
+
+    app.run(port=1340, access_log=True)
+    assert app.config.ACCESS_LOG == True
+
+
+async def test_config_access_log_passing_in_create_server(app):
+    assert app.config.ACCESS_LOG == True
+
+    @app.listener('after_server_start')
+    async def _request(sanic, loop):
+        app.stop()
+
+    await app.create_server(port=1341, access_log=False)
+    assert app.config.ACCESS_LOG == False
+
+    await app.create_server(port=1342, access_log=True)
+    assert app.config.ACCESS_LOG == True
+
+
+def test_config_rewrite_keep_alive():
+    config = Config()
+    assert config.KEEP_ALIVE == DEFAULT_CONFIG["KEEP_ALIVE"]
+    config = Config(keep_alive=True)
+    assert config.KEEP_ALIVE == True
+    config = Config(keep_alive=False)
+    assert config.KEEP_ALIVE == False
+
+    # use defaults
+    config = Config(defaults={"KEEP_ALIVE": False})
+    assert config.KEEP_ALIVE == False
+    config = Config(defaults={"KEEP_ALIVE": True})
+    assert config.KEEP_ALIVE == True

tests/test_keep_alive_timeout.py

@@ -3,13 +3,17 @@ from sanic import Sanic
 import asyncio
 from asyncio import sleep as aio_sleep
 from sanic.response import text
-from sanic.config import Config
 from sanic import server
 import aiohttp
 from aiohttp import TCPConnector
 from sanic.testing import SanicTestClient, HOST, PORT
 
 
+CONFIG_FOR_TESTS = {
+    "KEEP_ALIVE_TIMEOUT": 2,
+    "KEEP_ALIVE": True
+}
+
 class ReuseableTCPConnector(TCPConnector):
     def __init__(self, *args, **kwargs):
         super(ReuseableTCPConnector, self).__init__(*args, **kwargs)
@@ -141,7 +145,7 @@ class ReuseableSanicTestClient(SanicTestClient):
     # loop, so the changes above are required too.
     async def _local_request(self, method, uri, cookies=None, *args, **kwargs):
         request_keepalive = kwargs.pop(
-            "request_keepalive", Config.KEEP_ALIVE_TIMEOUT
+            "request_keepalive", CONFIG_FOR_TESTS['KEEP_ALIVE_TIMEOUT']
         )
         if uri.startswith(("http:", "https:", "ftp:", "ftps://" "//")):
             url = uri
@@ -191,12 +195,14 @@ class ReuseableSanicTestClient(SanicTestClient):
         return response
 
 
-Config.KEEP_ALIVE_TIMEOUT = 2
-Config.KEEP_ALIVE = True
 keep_alive_timeout_app_reuse = Sanic("test_ka_timeout_reuse")
 keep_alive_app_client_timeout = Sanic("test_ka_client_timeout")
 keep_alive_app_server_timeout = Sanic("test_ka_server_timeout")
 
+keep_alive_timeout_app_reuse.config.update(CONFIG_FOR_TESTS)
+keep_alive_app_client_timeout.config.update(CONFIG_FOR_TESTS)
+keep_alive_app_server_timeout.config.update(CONFIG_FOR_TESTS)
+
 
 @keep_alive_timeout_app_reuse.route("/1")
 async def handler1(request):

tests/test_middleware.py

@@ -73,6 +73,8 @@ def test_middleware_response_exception(app):
 
 
 def test_middleware_response_raise_cancelled_error(app, caplog):
+    app.config.RESPONSE_TIMEOUT = 1
+
     @app.middleware("response")
     async def process_response(request, response):
         raise CancelledError("CancelledError at response middleware")

tests/test_request_timeout.py

@@ -3,7 +3,6 @@ from json import JSONDecodeError
 from sanic import Sanic
 import asyncio
 from sanic.response import text
-from sanic.config import Config
 import aiohttp
 from aiohttp import TCPConnector
 from sanic.testing import SanicTestClient, HOST
@@ -183,9 +182,10 @@ class DelayableSanicTestClient(SanicTestClient):
                 return response
 
 
-Config.REQUEST_TIMEOUT = 0.6
 request_timeout_default_app = Sanic("test_request_timeout_default")
 request_no_timeout_app = Sanic("test_request_no_timeout")
+request_timeout_default_app.config.REQUEST_TIMEOUT = 0.6
+request_no_timeout_app.config.REQUEST_TIMEOUT = 0.6
 
 
 @request_timeout_default_app.route("/1")

tests/test_response_timeout.py

@@ -2,13 +2,15 @@ from sanic import Sanic
 import asyncio
 from sanic.response import text
 from sanic.exceptions import ServiceUnavailable
-from sanic.config import Config
 
-Config.RESPONSE_TIMEOUT = 1
 response_timeout_app = Sanic("test_response_timeout")
 response_timeout_default_app = Sanic("test_response_timeout_default")
 response_handler_cancelled_app = Sanic("test_response_handler_cancelled")
 
+response_timeout_app.config.RESPONSE_TIMEOUT = 1
+response_timeout_default_app.config.RESPONSE_TIMEOUT = 1
+response_handler_cancelled_app.config.RESPONSE_TIMEOUT = 1
+
 
 @response_timeout_app.route("/1")
 async def handler_1(request):

tests/test_worker.py

@@ -24,12 +24,58 @@ def gunicorn_worker():
     worker.kill()
 
 
+@pytest.fixture(scope='module')
+def gunicorn_worker_with_access_logs():
+    command = (
+        'gunicorn '
+        '--bind 127.0.0.1:1338 '
+        '--worker-class sanic.worker.GunicornWorker '
+        'examples.simple_server:app'
+    )
+    worker = subprocess.Popen(shlex.split(command), stdout=subprocess.PIPE)
+    time.sleep(2)
+    return worker
+
+
+@pytest.fixture(scope='module')
+def gunicorn_worker_with_env_var():
+    command = (
+        'env SANIC_ACCESS_LOG="False" '
+        'gunicorn '
+        '--bind 127.0.0.1:1339 '
+        '--worker-class sanic.worker.GunicornWorker '
+        '--log-level info '
+        'examples.simple_server:app'
+    )
+    worker = subprocess.Popen(shlex.split(command), stdout=subprocess.PIPE)
+    time.sleep(2)
+    return worker
+
+
 def test_gunicorn_worker(gunicorn_worker):
     with urllib.request.urlopen("http://localhost:1337/") as f:
         res = json.loads(f.read(100).decode())
     assert res["test"]
 
 
+def test_gunicorn_worker_no_logs(gunicorn_worker_with_env_var):
+    """
+    if SANIC_ACCESS_LOG was set to False do not show access logs
+    """
+    with urllib.request.urlopen('http://localhost:1339/') as _:
+        gunicorn_worker_with_env_var.kill()
+        assert not gunicorn_worker_with_env_var.stdout.read()
+
+
+def test_gunicorn_worker_with_logs(gunicorn_worker_with_access_logs):
+    """
+    default - show access logs
+    """
+    with urllib.request.urlopen('http://localhost:1338/') as _:
+        gunicorn_worker_with_access_logs.kill()
+        assert b"(sanic.access)[INFO][127.0.0.1" in gunicorn_worker_with_access_logs.stdout.read()
+
+
 class GunicornTestWorker(GunicornWorker):
     def __init__(self):
         self.app = mock.Mock()