From 17364dce06dcdebb42c0089d23f5748b2e7fe728 Mon Sep 17 00:00:00 2001 From: hellysmile Date: Thu, 12 Oct 2017 03:03:12 +0300 Subject: [PATCH 01/11] Initial access_log_factory support. --- aiohttp/abc.py | 10 ++++++++++ aiohttp/helpers.py | 5 +++-- aiohttp/web_protocol.py | 3 ++- 3 files changed, 15 insertions(+), 3 deletions(-) diff --git a/aiohttp/abc.py b/aiohttp/abc.py index 0d2854e66ae..947a85b0465 100644 --- a/aiohttp/abc.py +++ b/aiohttp/abc.py @@ -146,3 +146,13 @@ def write_eof(self, chunk=b''): @abstractmethod def drain(self): """Flush the write buffer.""" + + +class AbstractAccessLogger(ABC): + + def __init__(self, logger, log_format): + self.logger = logger + + @abstractmethod + def log(self, request, response, time): + """Emit log to logger""" diff --git a/aiohttp/helpers.py b/aiohttp/helpers.py index bbfb82b238f..df96fbb13de 100644 --- a/aiohttp/helpers.py +++ b/aiohttp/helpers.py @@ -23,6 +23,7 @@ from yarl import URL from . import hdrs +from .abc import AbstractAccessLogger from .log import client_logger @@ -346,7 +347,7 @@ def content_disposition_header(disptype, quote_fields=True, **params): return value -class AccessLogger: +class AccessLogger(AbstractAccessLogger): """Helper object to log access. Usage: @@ -400,7 +401,7 @@ def __init__(self, logger, log_format=LOG_FORMAT): :param log_format: apache compatible log format """ - self.logger = logger + super().__init__(logger, log_format=log_format) _compiled_format = AccessLogger._FORMAT_CACHE.get(log_format) if not _compiled_format: diff --git a/aiohttp/web_protocol.py b/aiohttp/web_protocol.py index 8bf9149aa00..90ecd7d8d73 100644 --- a/aiohttp/web_protocol.py +++ b/aiohttp/web_protocol.py @@ -83,6 +83,7 @@ def __init__(self, manager, *, loop=None, tcp_keepalive=True, slow_request_timeout=None, logger=server_logger, + access_log_factory=helpers.AccessLogger, access_log=access_logger, access_log_format=helpers.AccessLogger.LOG_FORMAT, debug=False, @@ -138,7 +139,7 @@ def __init__(self, manager, *, loop=None, self.debug = debug self.access_log = access_log if access_log: - self.access_logger = helpers.AccessLogger( + self.access_logger = access_log_factory( access_log, access_log_format) else: self.access_logger = None From 9dcb69d113471485af7c49f9df16aaa4add57e0e Mon Sep 17 00:00:00 2001 From: hellysmile Date: Thu, 12 Oct 2017 03:08:18 +0300 Subject: [PATCH 02/11] Added changes. --- changes/2315.feature | 1 + 1 file changed, 1 insertion(+) create mode 100644 changes/2315.feature diff --git a/changes/2315.feature b/changes/2315.feature new file mode 100644 index 00000000000..933669e6c85 --- /dev/null +++ b/changes/2315.feature @@ -0,0 +1 @@ +aiohttp.wep.Application.make_handler support access_log_factory From bff0c8ea155c5ebe68737e552941381f08fa0a0e Mon Sep 17 00:00:00 2001 From: hellysmile Date: Thu, 12 Oct 2017 14:53:26 +0300 Subject: [PATCH 03/11] abstraction level changes for AccessLogger. --- aiohttp/abc.py | 14 ++++++++++++++ aiohttp/helpers.py | 33 +++++++++++---------------------- aiohttp/web_protocol.py | 4 ++-- 3 files changed, 27 insertions(+), 24 deletions(-) diff --git a/aiohttp/abc.py b/aiohttp/abc.py index 947a85b0465..76ff299db64 100644 --- a/aiohttp/abc.py +++ b/aiohttp/abc.py @@ -152,7 +152,21 @@ class AbstractAccessLogger(ABC): def __init__(self, logger, log_format): self.logger = logger + self.log_format = log_format @abstractmethod + def _log(self, request, response, time): + """ + + :param request: Request object. + :param response: Response object. + :param float time: Time taken to serve the request. + """ + def log(self, request, response, time): """Emit log to logger""" + + try: + self._log(request, response, time) + except Exception: + self.logger.exception("Error in logging") diff --git a/aiohttp/helpers.py b/aiohttp/helpers.py index df96fbb13de..98f69b3f9e9 100644 --- a/aiohttp/helpers.py +++ b/aiohttp/helpers.py @@ -513,31 +513,20 @@ def _format_line(self, request, response, time): return ((key, method(request, response, time)) for key, method in self._methods) - def log(self, request, response, time): - """Log access. - - :param message: Request object. May be None. - :param environ: Environment dict. May be None. - :param response: Response object. - :param transport: Tansport object. May be None - :param float time: Time taken to serve the request. - """ - try: - fmt_info = self._format_line(request, response, time) + def _log(self, request, response, time): + fmt_info = self._format_line(request, response, time) - values = list() - extra = dict() - for key, value in fmt_info: - values.append(value) + values = list() + extra = dict() + for key, value in fmt_info: + values.append(value) - if key.__class__ is str: - extra[key] = value - else: - extra[key[0]] = {key[1]: value} + if key.__class__ is str: + extra[key] = value + else: + extra[key[0]] = {key[1]: value} - self.logger.info(self._log_format % tuple(values), extra=extra) - except Exception: - self.logger.exception("Error in logging") + self.logger.info(self._log_format % tuple(values), extra=extra) class reify: diff --git a/aiohttp/web_protocol.py b/aiohttp/web_protocol.py index 90ecd7d8d73..385d760f209 100644 --- a/aiohttp/web_protocol.py +++ b/aiohttp/web_protocol.py @@ -83,7 +83,7 @@ def __init__(self, manager, *, loop=None, tcp_keepalive=True, slow_request_timeout=None, logger=server_logger, - access_log_factory=helpers.AccessLogger, + access_log_class=helpers.AccessLogger, access_log=access_logger, access_log_format=helpers.AccessLogger.LOG_FORMAT, debug=False, @@ -139,7 +139,7 @@ def __init__(self, manager, *, loop=None, self.debug = debug self.access_log = access_log if access_log: - self.access_logger = access_log_factory( + self.access_logger = access_log_class( access_log, access_log_format) else: self.access_logger = None From 07dd227dbbd4cde729af9aaff6d78618de78cc96 Mon Sep 17 00:00:00 2001 From: hellysmile Date: Thu, 12 Oct 2017 14:58:02 +0300 Subject: [PATCH 04/11] Added RequestHandler docstrings. --- aiohttp/web_protocol.py | 3 +++ 1 file changed, 3 insertions(+) diff --git a/aiohttp/web_protocol.py b/aiohttp/web_protocol.py index 385d760f209..1bb3eaa3a84 100644 --- a/aiohttp/web_protocol.py +++ b/aiohttp/web_protocol.py @@ -61,6 +61,9 @@ class RequestHandler(asyncio.streams.FlowControlMixin, asyncio.Protocol): :param logger: custom logger object :type logger: aiohttp.log.server_logger + :param access_log_class: custom class for access_logger + :type access_log_class: aiohttp.abc.AbstractAccessLogger + :param access_log: custom logging object :type access_log: aiohttp.log.server_logger From 9a6e28b512ce490af6efacd342debbf49a490dc3 Mon Sep 17 00:00:00 2001 From: hellysmile Date: Thu, 12 Oct 2017 14:58:54 +0300 Subject: [PATCH 05/11] Fix changes naming. --- changes/2315.feature | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/changes/2315.feature b/changes/2315.feature index 933669e6c85..6d39a01e0ce 100644 --- a/changes/2315.feature +++ b/changes/2315.feature @@ -1 +1 @@ -aiohttp.wep.Application.make_handler support access_log_factory +aiohttp.wep.Application.make_handler support access_log_class From bbd63830e6f74a68d5529fd70885241209cc9e34 Mon Sep 17 00:00:00 2001 From: hellysmile Date: Thu, 12 Oct 2017 16:25:40 +0300 Subject: [PATCH 06/11] Added access_log_class check for Application.make_handler --- aiohttp/web.py | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/aiohttp/web.py b/aiohttp/web.py index 68ba8e2ab70..086689d6ea2 100644 --- a/aiohttp/web.py +++ b/aiohttp/web.py @@ -14,7 +14,7 @@ from . import (hdrs, web_exceptions, web_fileresponse, web_middlewares, web_protocol, web_request, web_response, web_server, web_urldispatcher, web_ws) -from .abc import AbstractMatchInfo, AbstractRouter +from .abc import AbstractAccessLogger, AbstractMatchInfo, AbstractRouter from .frozenlist import FrozenList from .http import HttpVersion # noqa from .log import access_logger, web_logger @@ -230,6 +230,14 @@ def middlewares(self): return self._middlewares def make_handler(self, *, loop=None, **kwargs): + if 'access_log_class' in kwargs: + access_log_class = kwargs['access_log_class'] + + assert issubclass(access_log_class, AbstractAccessLogger), ( + '{} must be subclass of ' + 'aiohttp.abc.AbstractAccessLogger'.format(access_log_class) + ) + self._set_loop(loop) self.freeze() From 8f19815f17afd096bc7f311c2e85230e49193dc4 Mon Sep 17 00:00:00 2001 From: hellysmile Date: Thu, 12 Oct 2017 22:13:07 +0300 Subject: [PATCH 07/11] Added basic tests for access_log_class. --- tests/test_helpers.py | 25 +++++++++++++++++++++++++ tests/test_web_application.py | 25 ++++++++++++++++++++++++- 2 files changed, 49 insertions(+), 1 deletion(-) diff --git a/tests/test_helpers.py b/tests/test_helpers.py index c68b317a996..1c6a94bd283 100644 --- a/tests/test_helpers.py +++ b/tests/test_helpers.py @@ -10,6 +10,7 @@ from yarl import URL from aiohttp import helpers +from aiohttp.abc import AbstractAccessLogger # -------------------- coro guard -------------------------------- @@ -256,6 +257,30 @@ def test_logger_no_transport(): mock_logger.info.assert_called_with("-", extra={'remote_address': '-'}) +def test_logger_abc(): + class Logger(AbstractAccessLogger): + def _log(self, request, response, time): + 1 / 0 + + mock_logger = mock.Mock() + access_logger = Logger(mock_logger, None) + access_logger.log(None, None, None) + mock_logger.exception.assert_called_with("Error in logging") + + class Logger(AbstractAccessLogger): + def _log(self, request, response, time): + self.logger.info(self.log_format.format( + request=request, + response=response, + time=time + )) + + mock_logger = mock.Mock() + access_logger = Logger(mock_logger, '{request} {response} {time}') + access_logger.log('request', 'response', 1) + mock_logger.info.assert_called_with('request response 1') + + class TestReify: def test_reify(self): diff --git a/tests/test_web_application.py b/tests/test_web_application.py index 9e141207702..b4e0506f933 100644 --- a/tests/test_web_application.py +++ b/tests/test_web_application.py @@ -4,7 +4,7 @@ import pytest from aiohttp import helpers, log, web -from aiohttp.abc import AbstractRouter +from aiohttp.abc import AbstractAccessLogger, AbstractRouter def test_app_ctor(loop): @@ -79,6 +79,29 @@ def test_app_make_handler_args(loop, mocker): loop=loop, debug=mock.ANY, test=True) +def test_app_make_handler_access_log_class(loop, mocker): + class Logger: + pass + + app = web.Application() + + with pytest.raises(AssertionError): + app.make_handler(access_log_class=Logger, loop=loop) + + class Logger(AbstractAccessLogger): + + def _log(self, request, response, time): + self.logger.info('msg') + + srv = mocker.patch('aiohttp.web.Server') + + app.make_handler(access_log_class=Logger, loop=loop) + srv.assert_called_with(app._handle, + access_log_class=Logger, + request_factory=app._make_request, + loop=loop, debug=mock.ANY) + + @asyncio.coroutine def test_app_register_on_finish(): app = web.Application() From ced7bad8394bc6cd1ed57074a0dd0278f555b978 Mon Sep 17 00:00:00 2001 From: hellysmile Date: Thu, 12 Oct 2017 23:54:39 +0300 Subject: [PATCH 08/11] Added docs for access_log_class --- docs/abc.rst | 24 +++++++++++++++++++++--- docs/logging.rst | 14 ++++++++++++++ docs/web_reference.rst | 3 +++ 3 files changed, 38 insertions(+), 3 deletions(-) diff --git a/docs/abc.rst b/docs/abc.rst index 4faf7e3f2c4..646d85350c5 100644 --- a/docs/abc.rst +++ b/docs/abc.rst @@ -35,7 +35,7 @@ Not Allowed*. :meth:`AbstractMatchInfo.handler` raises :attr:`~AbstractMatchInfo.http_exception` on call. -.. class:: AbstractRouter +.. class:: aiohttp.abc.AbstractRouter Abstract router, :class:`aiohttp.web.Application` accepts it as *router* parameter and returns as @@ -54,7 +54,7 @@ Not Allowed*. :meth:`AbstractMatchInfo.handler` raises :return: :class:`AbstractMatchInfo` instance. -.. class:: AbstractMatchInfo +.. class:: aiohttp.abc.AbstractMatchInfo Abstract *match info*, returned by :meth:`AbstractRouter.resolve` call. @@ -102,7 +102,7 @@ attribute. Abstract Cookie Jar ------------------- -.. class:: AbstractCookieJar +.. class:: aiohttp.abc.AbstractCookieJar The cookie jar instance is available as :attr:`ClientSession.cookie_jar`. @@ -146,3 +146,21 @@ Abstract Cookie Jar :return: :class:`http.cookies.SimpleCookie` with filtered cookies for given URL. + +Abstract Abstract Access Logger +------------------------------- + +.. class:: aiohttp.abc.AbstractAccessLogger + + An abstract class, base for all :class:`RequestHandler` + ``access_logger`` implementations + + Method ``_log`` should be overridden. + + .. method:: _log(request, response, time) + + :param request: :class:`aiohttp.web.Request` object. + + :param response: :class:`aiohttp.web.Response` object. + + :param float time: Time taken to serve the request. diff --git a/docs/logging.rst b/docs/logging.rst index 7695676ebb1..f59013e8baf 100644 --- a/docs/logging.rst +++ b/docs/logging.rst @@ -87,6 +87,20 @@ Default access log format is:: '%a %l %u %t "%r" %s %b "%{Referrer}i" "%{User-Agent}i"' +.. versionadded:: 2.3.0 + +*access_log_class* introduced. + +Example of drop-in replacement for :class:`aiohttp.helpers.AccessLogger`:: + + from aiohttp.abc import AbstractAccessLogger + + class AccessLogger(AbstractAccessLogger): + + def _log(self, request, response, time): + self.logger.info(f'{request.remote} ' + f'"{request.method} {request.path}"" ' + f'done in {time}s: {request.status}') .. note:: diff --git a/docs/web_reference.rst b/docs/web_reference.rst index ece01e3a56a..10b91894b01 100644 --- a/docs/web_reference.rst +++ b/docs/web_reference.rst @@ -1347,6 +1347,9 @@ duplicated like one using :meth:`Application.copy`. :data:`aiohttp.log.server_logger`. :param access_log: Custom logging object. Default: :data:`aiohttp.log.access_logger`. + :param access_log_class: class for `access_logger`. Default: + :data:`aiohttp.helpers.AccessLogger`. + Must to be a subclass of :class:`aiohttp.abc.AbstractAccessLogger`. :param str access_log_format: Access log format string. Default: :attr:`helpers.AccessLogger.LOG_FORMAT`. :param bool debug: Switches debug mode. Default: ``False``. From fc75be39f2d2d877963411f9dd503a66b16fb3a0 Mon Sep 17 00:00:00 2001 From: hellysmile Date: Thu, 12 Oct 2017 23:58:16 +0300 Subject: [PATCH 09/11] Fix typo request->response --- docs/logging.rst | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/docs/logging.rst b/docs/logging.rst index f59013e8baf..5e67600cf2a 100644 --- a/docs/logging.rst +++ b/docs/logging.rst @@ -99,8 +99,8 @@ Example of drop-in replacement for :class:`aiohttp.helpers.AccessLogger`:: def _log(self, request, response, time): self.logger.info(f'{request.remote} ' - f'"{request.method} {request.path}"" ' - f'done in {time}s: {request.status}') + f'"{request.method} {request.path} ' + f'done in {time}s: {response.status}') .. note:: From f0ac3e3c584e4b091d7ba0c3df6a2ed79bcea029 Mon Sep 17 00:00:00 2001 From: hellysmile Date: Fri, 13 Oct 2017 15:49:40 +0300 Subject: [PATCH 10/11] _log -> log --- aiohttp/abc.py | 13 ------------- aiohttp/helpers.py | 25 ++++++++++++++----------- aiohttp/web.py | 16 +++++++++------- docs/abc.rst | 4 ++-- docs/logging.rst | 2 +- tests/test_helpers.py | 9 +++++---- tests/test_web_application.py | 6 ++++-- 7 files changed, 35 insertions(+), 40 deletions(-) diff --git a/aiohttp/abc.py b/aiohttp/abc.py index 76ff299db64..3ca9a5d5b5c 100644 --- a/aiohttp/abc.py +++ b/aiohttp/abc.py @@ -155,18 +155,5 @@ def __init__(self, logger, log_format): self.log_format = log_format @abstractmethod - def _log(self, request, response, time): - """ - - :param request: Request object. - :param response: Response object. - :param float time: Time taken to serve the request. - """ - def log(self, request, response, time): """Emit log to logger""" - - try: - self._log(request, response, time) - except Exception: - self.logger.exception("Error in logging") diff --git a/aiohttp/helpers.py b/aiohttp/helpers.py index 98f69b3f9e9..a672f0183b4 100644 --- a/aiohttp/helpers.py +++ b/aiohttp/helpers.py @@ -513,20 +513,23 @@ def _format_line(self, request, response, time): return ((key, method(request, response, time)) for key, method in self._methods) - def _log(self, request, response, time): - fmt_info = self._format_line(request, response, time) + def log(self, request, response, time): + try: + fmt_info = self._format_line(request, response, time) - values = list() - extra = dict() - for key, value in fmt_info: - values.append(value) + values = list() + extra = dict() + for key, value in fmt_info: + values.append(value) - if key.__class__ is str: - extra[key] = value - else: - extra[key[0]] = {key[1]: value} + if key.__class__ is str: + extra[key] = value + else: + extra[key[0]] = {key[1]: value} - self.logger.info(self._log_format % tuple(values), extra=extra) + self.logger.info(self._log_format % tuple(values), extra=extra) + except Exception: + self.logger.exception("Error in logging") class reify: diff --git a/aiohttp/web.py b/aiohttp/web.py index 84459a34bfe..4a9d0276e74 100644 --- a/aiohttp/web.py +++ b/aiohttp/web.py @@ -17,6 +17,7 @@ web_urldispatcher, web_ws) from .abc import AbstractAccessLogger, AbstractMatchInfo, AbstractRouter from .frozenlist import FrozenList +from .helpers import AccessLogger from .http import HttpVersion # noqa from .log import access_logger, web_logger from .signals import FuncSignal, PostSignal, PreSignal, Signal @@ -230,14 +231,14 @@ def router(self): def middlewares(self): return self._middlewares - def make_handler(self, *, loop=None, **kwargs): - if 'access_log_class' in kwargs: - access_log_class = kwargs['access_log_class'] + def make_handler(self, *, + loop=None, + access_log_class=AccessLogger, + **kwargs): - assert issubclass(access_log_class, AbstractAccessLogger), ( - '{} must be subclass of ' - 'aiohttp.abc.AbstractAccessLogger'.format(access_log_class) - ) + if not issubclass(access_log_class, AbstractAccessLogger): + raise TypeError('access_log_class must be subclass of ' + 'aiohttp.abc.AbstractAccessLogger') self._set_loop(loop) self.freeze() @@ -248,6 +249,7 @@ def make_handler(self, *, loop=None, **kwargs): kwargs[k] = v return Server(self._handle, request_factory=self._make_request, + access_log_class=access_log_class, loop=self.loop, **kwargs) @asyncio.coroutine diff --git a/docs/abc.rst b/docs/abc.rst index 646d85350c5..057d609e268 100644 --- a/docs/abc.rst +++ b/docs/abc.rst @@ -155,9 +155,9 @@ Abstract Abstract Access Logger An abstract class, base for all :class:`RequestHandler` ``access_logger`` implementations - Method ``_log`` should be overridden. + Method ``log`` should be overridden. - .. method:: _log(request, response, time) + .. method:: log(request, response, time) :param request: :class:`aiohttp.web.Request` object. diff --git a/docs/logging.rst b/docs/logging.rst index 5e67600cf2a..d9fc51155d5 100644 --- a/docs/logging.rst +++ b/docs/logging.rst @@ -97,7 +97,7 @@ Example of drop-in replacement for :class:`aiohttp.helpers.AccessLogger`:: class AccessLogger(AbstractAccessLogger): - def _log(self, request, response, time): + def log(self, request, response, time): self.logger.info(f'{request.remote} ' f'"{request.method} {request.path} ' f'done in {time}s: {response.status}') diff --git a/tests/test_helpers.py b/tests/test_helpers.py index 1c6a94bd283..3d94703d605 100644 --- a/tests/test_helpers.py +++ b/tests/test_helpers.py @@ -259,16 +259,17 @@ def test_logger_no_transport(): def test_logger_abc(): class Logger(AbstractAccessLogger): - def _log(self, request, response, time): + def log(self, request, response, time): 1 / 0 mock_logger = mock.Mock() access_logger = Logger(mock_logger, None) - access_logger.log(None, None, None) - mock_logger.exception.assert_called_with("Error in logging") + + with pytest.raises(ZeroDivisionError): + access_logger.log(None, None, None) class Logger(AbstractAccessLogger): - def _log(self, request, response, time): + def log(self, request, response, time): self.logger.info(self.log_format.format( request=request, response=response, diff --git a/tests/test_web_application.py b/tests/test_web_application.py index b4e0506f933..2805b2babdd 100644 --- a/tests/test_web_application.py +++ b/tests/test_web_application.py @@ -65,6 +65,7 @@ def test_app_make_handler_debug_exc(loop, mocker, debug): app.make_handler(loop=loop) srv.assert_called_with(app._handle, request_factory=app._make_request, + access_log_class=mock.ANY, loop=loop, debug=debug) @@ -76,6 +77,7 @@ def test_app_make_handler_args(loop, mocker): app.make_handler(loop=loop) srv.assert_called_with(app._handle, request_factory=app._make_request, + access_log_class=mock.ANY, loop=loop, debug=mock.ANY, test=True) @@ -85,12 +87,12 @@ class Logger: app = web.Application() - with pytest.raises(AssertionError): + with pytest.raises(TypeError): app.make_handler(access_log_class=Logger, loop=loop) class Logger(AbstractAccessLogger): - def _log(self, request, response, time): + def log(self, request, response, time): self.logger.info('msg') srv = mocker.patch('aiohttp.web.Server') From db02580f4dde9ff551ebaa928858464dc10939b0 Mon Sep 17 00:00:00 2001 From: hellysmile Date: Fri, 13 Oct 2017 17:01:58 +0300 Subject: [PATCH 11/11] Added more details to TypeError regarding access_log_class. --- aiohttp/web.py | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/aiohttp/web.py b/aiohttp/web.py index 4a9d0276e74..4b5a1de2ff6 100644 --- a/aiohttp/web.py +++ b/aiohttp/web.py @@ -237,8 +237,10 @@ def make_handler(self, *, **kwargs): if not issubclass(access_log_class, AbstractAccessLogger): - raise TypeError('access_log_class must be subclass of ' - 'aiohttp.abc.AbstractAccessLogger') + raise TypeError( + 'access_log_class must be subclass of ' + 'aiohttp.abc.AbstractAccessLogger, got {}'.format( + access_log_class)) self._set_loop(loop) self.freeze()