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

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

docs/gunicorn.rst

@@ -1,3 +1,5 @@
+.. _deployment-using-gunicorn:
+
 Deployment using Gunicorn
 =========================
 

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 <http://docs.gunicorn.org/en/latest/index.html>`_ is used for
+   :ref:`deployment <deployment-using-gunicorn>` 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

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