From 21aae8299f040349689ae2e0dc09ac880bb9c858 Mon Sep 17 00:00:00 2001 From: Eugene Naydenov Date: Thu, 25 Aug 2016 14:13:58 +0300 Subject: [PATCH] Fix access_log_format in `GunicornWebWorker` (#1117) - Replace default gunicorn's access log format with the default aiohttp's one. - Use regular expression to check if the log format passed as a gunicorn's option `access_logformat` uses Gunicorn's formatting style and in this case raise a `ValueError`. - Add a note describing this behavior to the `Logging` section of the documentation. --- aiohttp/worker.py | 24 ++++++++++++++++++++++-- docs/gunicorn.rst | 2 ++ docs/logging.rst | 14 ++++++++++++++ tests/test_worker.py | 27 ++++++++++++++++++++++++++- 4 files changed, 64 insertions(+), 3 deletions(-) diff --git a/aiohttp/worker.py b/aiohttp/worker.py index dff4979d0f5..a6771bcee75 100644 --- a/aiohttp/worker.py +++ b/aiohttp/worker.py @@ -2,19 +2,24 @@ import asyncio import os +import re import signal import ssl import sys import gunicorn.workers.base as base -from aiohttp.helpers import ensure_future +from gunicorn.config import AccessLogFormat as GunicornAccessLogFormat +from aiohttp.helpers import AccessLogger, ensure_future __all__ = ('GunicornWebWorker', 'GunicornUVLoopWebWorker') class GunicornWebWorker(base.Worker): + DEFAULT_AIOHTTP_LOG_FORMAT = AccessLogger.LOG_FORMAT + DEFAULT_GUNICORN_LOG_FORMAT = GunicornAccessLogFormat.default + def __init__(self, *args, **kw): # pragma: no cover super().__init__(*args, **kw) @@ -48,7 +53,8 @@ def make_handler(self, app): timeout=self.cfg.timeout, keep_alive=self.cfg.keepalive, access_log=self.log.access_log, - access_log_format=self.cfg.access_log_format) + access_log_format=self._get_valid_log_format( + self.cfg.access_log_format)) @asyncio.coroutine def close(self): @@ -158,6 +164,20 @@ def _create_ssl_context(cfg): ctx.set_ciphers(cfg.ciphers) return ctx + def _get_valid_log_format(self, source_format): + if source_format == self.DEFAULT_GUNICORN_LOG_FORMAT: + return self.DEFAULT_AIOHTTP_LOG_FORMAT + elif re.search(r'%\([^\)]+\)', source_format): + raise ValueError( + "Gunicorn's style options in form of `%(name)s` are not " + "supported for the log formatting. Please use aiohttp's " + "format specification to configure access log formatting: " + "http://aiohttp.readthedocs.io/en/stable/logging.html" + "#format-specification" + ) + else: + return source_format + class GunicornUVLoopWebWorker(GunicornWebWorker): diff --git a/docs/gunicorn.rst b/docs/gunicorn.rst index 98deb9c7f44..739835c86f2 100644 --- a/docs/gunicorn.rst +++ b/docs/gunicorn.rst @@ -1,3 +1,5 @@ +.. _deployment-using-gunicorn: + Deployment using Gunicorn ========================= diff --git a/docs/logging.rst b/docs/logging.rst index 54ce9f22b10..015a3fe86f7 100644 --- a/docs/logging.rst +++ b/docs/logging.rst @@ -89,6 +89,16 @@ Default access log format is:: '%a %l %u %t "%r" %s %b "%{Referrer}i" "%{User-Agent}i"' +.. note:: + + When `Gunicorn `_ is used for + :ref:`deployment ` its default access log format + will be automatically replaced with the default aiohttp's access log format. + + If Gunicorn's option access_logformat_ is + specified explicitly it should use aiohttp's format specification. + + Error logs ---------- @@ -100,3 +110,7 @@ The log is enabled by default. To use different logger name please specify *logger* parameter (:class:`logging.Logger` instance) on performing :meth:`aiohttp.web.Application.make_handler` call. + + +.. _access_logformat: + http://docs.gunicorn.org/en/stable/settings.html#access-log-format diff --git a/tests/test_worker.py b/tests/test_worker.py index 7e0fac908ad..4a3442db23d 100644 --- a/tests/test_worker.py +++ b/tests/test_worker.py @@ -17,6 +17,10 @@ uvloop = None +WRONG_LOG_FORMAT = '%a "%{Referrer}i" %(h)s %(l)s %s' +ACCEPTABLE_LOG_FORMAT = '%a "%{Referrer}i" %s' + + class BaseTestWorker: def __init__(self): @@ -89,14 +93,32 @@ def test_init_signals(worker): assert worker.loop.add_signal_handler.called -def test_make_handler(worker): +def test_make_handler(worker, mocker): worker.wsgi = mock.Mock() worker.loop = mock.Mock() worker.log = mock.Mock() worker.cfg = mock.Mock() + worker.cfg.access_log_format = ACCEPTABLE_LOG_FORMAT + mocker.spy(worker, '_get_valid_log_format') f = worker.make_handler(worker.wsgi) assert f is worker.wsgi.make_handler.return_value + assert worker._get_valid_log_format.called + + +@pytest.mark.parametrize('source,result', [ + (ACCEPTABLE_LOG_FORMAT, ACCEPTABLE_LOG_FORMAT), + (AsyncioWorker.DEFAULT_GUNICORN_LOG_FORMAT, + AsyncioWorker.DEFAULT_AIOHTTP_LOG_FORMAT), +]) +def test__get_valid_log_format_ok(worker, source, result): + assert result == worker._get_valid_log_format(source) + + +def test__get_valid_log_format_exc(worker): + with pytest.raises(ValueError) as exc: + worker._get_valid_log_format(WRONG_LOG_FORMAT) + assert '%(name)s' in str(exc) @asyncio.coroutine @@ -115,6 +137,7 @@ def test__run_ok(worker, loop): worker.wsgi.make_handler.return_value.requests_count = 1 worker.cfg.max_requests = 100 worker.cfg.is_ssl = True + worker.cfg.access_log_format = ACCEPTABLE_LOG_FORMAT ssl_context = mock.Mock() with mock.patch('ssl.SSLContext', return_value=ssl_context): @@ -205,6 +228,7 @@ def test__run_ok_no_max_requests(worker, loop): worker.loop = loop loop.create_server = make_mocked_coro(sock) worker.wsgi.make_handler.return_value.requests_count = 1 + worker.cfg.access_log_format = ACCEPTABLE_LOG_FORMAT worker.cfg.max_requests = 0 worker.cfg.is_ssl = True @@ -239,6 +263,7 @@ def test__run_ok_max_requests_exceeded(worker, loop): worker.loop = loop loop.create_server = make_mocked_coro(sock) worker.wsgi.make_handler.return_value.requests_count = 15 + worker.cfg.access_log_format = ACCEPTABLE_LOG_FORMAT worker.cfg.max_requests = 10 worker.cfg.is_ssl = True