Extract AccessLog into a separate module (#3336)

Author: asvetlov

aiohttp/base_protocol.py

@@ -10,9 +10,8 @@ class BaseProtocol(asyncio.Protocol):
 
     def __init__(self, loop: Optional[asyncio.AbstractEventLoop]=None) -> None:
         if loop is None:
-            self._loop = asyncio.get_event_loop()
-        else:
-            self._loop = loop
+            loop = asyncio.get_event_loop()
+        self._loop = loop  # type: asyncio.AbstractEventLoop
         self._paused = False
         self._drain_waiter = None  # type: Optional[asyncio.Future[None]]
         self._connection_lost = False

aiohttp/client_proto.py

@@ -1,4 +1,6 @@
+import asyncio
 from contextlib import suppress
+from typing import Optional
 
 from .base_protocol import BaseProtocol
 from .client_exceptions import (ClientOSError, ClientPayloadError,
@@ -10,7 +12,10 @@
 class ResponseHandler(BaseProtocol, DataQueue):
     """Helper class to adapt between Protocol and StreamReader."""
 
-    def __init__(self, *, loop=None):
+    def __init__(self, *,
+                 loop: Optional[asyncio.AbstractEventLoop]=None) -> None:
+        if loop is None:
+            loop = asyncio.get_event_loop()
         BaseProtocol.__init__(self, loop=loop)
         DataQueue.__init__(self, loop=loop)
 

aiohttp/helpers.py

@@ -4,10 +4,8 @@
 import base64
 import binascii
 import cgi
-import datetime
 import functools
 import inspect
-import logging
 import netrc
 import os
 import re
@@ -19,9 +17,9 @@
 from math import ceil
 from pathlib import Path
 from types import TracebackType
-from typing import (TYPE_CHECKING, Any, Callable, Dict, Iterable, Iterator,
-                    List, Mapping, Optional, Pattern, Tuple, Type, TypeVar,
-                    Union, cast)
+from typing import (Any, Callable, Dict, Iterable, Iterator, List,  # noqa
+                    Mapping, Optional, Pattern, Tuple, Type, TypeVar, Union,
+                    cast)
 from urllib.parse import quote
 from urllib.request import getproxies
 
@@ -31,7 +29,6 @@
 from yarl import URL
 
 from . import hdrs
-from .abc import AbstractAccessLogger
 from .log import client_logger
 from .typedefs import PathLike  # noqa
 
@@ -51,12 +48,6 @@
     from typing_extensions import ContextManager
 
 
-if TYPE_CHECKING:  # pragma: no cover
-    # run in mypy mode only to prevent circular imports
-    from .web_request import BaseRequest  # noqa
-    from .web_response import StreamResponse  # noqa
-
-
 _T = TypeVar('_T')
 
 
@@ -67,7 +58,7 @@
 # for compatibility with older versions
 DEBUG = (getattr(sys.flags, 'dev_mode', False) or
          (not sys.flags.ignore_environment and
-          bool(os.environ.get('PYTHONASYNCIODEBUG'))))
+          bool(os.environ.get('PYTHONASYNCIODEBUG'))))  # type: bool
 
 
 CHAR = set(chr(i) for i in range(0, 128))
@@ -323,231 +314,6 @@ def content_disposition_header(disptype: str,
     return value
 
 
-KeyMethod = namedtuple('KeyMethod', 'key method')
-
-
-class AccessLogger(AbstractAccessLogger):
-    """Helper object to log access.
-
-    Usage:
-        log = logging.getLogger("spam")
-        log_format = "%a %{User-Agent}i"
-        access_logger = AccessLogger(log, log_format)
-        access_logger.log(request, response, time)
-
-    Format:
-        %%  The percent sign
-        %a  Remote IP-address (IP-address of proxy if using reverse proxy)
-        %t  Time when the request was started to process
-        %P  The process ID of the child that serviced the request
-        %r  First line of request
-        %s  Response status code
-        %b  Size of response in bytes, including HTTP headers
-        %T  Time taken to serve the request, in seconds
-        %Tf Time taken to serve the request, in seconds with floating fraction
-            in .06f format
-        %D  Time taken to serve the request, in microseconds
-        %{FOO}i  request.headers['FOO']
-        %{FOO}o  response.headers['FOO']
-        %{FOO}e  os.environ['FOO']
-
-    """
-    LOG_FORMAT_MAP = {
-        'a': 'remote_address',
-        't': 'request_start_time',
-        'P': 'process_id',
-        'r': 'first_request_line',
-        's': 'response_status',
-        'b': 'response_size',
-        'T': 'request_time',
-        'Tf': 'request_time_frac',
-        'D': 'request_time_micro',
-        'i': 'request_header',
-        'o': 'response_header',
-    }
-
-    LOG_FORMAT = '%a %t "%r" %s %b "%{Referer}i" "%{User-Agent}i"'
-    FORMAT_RE = re.compile(r'%(\{([A-Za-z0-9\-_]+)\}([ioe])|[atPrsbOD]|Tf?)')
-    CLEANUP_RE = re.compile(r'(%[^s])')
-    _FORMAT_CACHE = {}  # type: Dict[str, Tuple[str, List[KeyMethod]]]
-
-    def __init__(self, logger: logging.Logger,
-                 log_format: str=LOG_FORMAT) -> None:
-        """Initialise the logger.
-
-        logger is a logger object to be used for logging.
-        log_format is an string with apache compatible log format description.
-
-        """
-        super().__init__(logger, log_format=log_format)
-
-        _compiled_format = AccessLogger._FORMAT_CACHE.get(log_format)
-        if not _compiled_format:
-            _compiled_format = self.compile_format(log_format)
-            AccessLogger._FORMAT_CACHE[log_format] = _compiled_format
-
-        self._log_format, self._methods = _compiled_format
-
-    def compile_format(self, log_format: str) -> Tuple[str, List[KeyMethod]]:
-        """Translate log_format into form usable by modulo formatting
-
-        All known atoms will be replaced with %s
-        Also methods for formatting of those atoms will be added to
-        _methods in appropriate order
-
-        For example we have log_format = "%a %t"
-        This format will be translated to "%s %s"
-        Also contents of _methods will be
-        [self._format_a, self._format_t]
-        These method will be called and results will be passed
-        to translated string format.
-
-        Each _format_* method receive 'args' which is list of arguments
-        given to self.log
-
-        Exceptions are _format_e, _format_i and _format_o methods which
-        also receive key name (by functools.partial)
-
-        """
-        # list of (key, method) tuples, we don't use an OrderedDict as users
-        # can repeat the same key more than once
-        methods = list()
-
-        for atom in self.FORMAT_RE.findall(log_format):
-            if atom[1] == '':
-                format_key1 = self.LOG_FORMAT_MAP[atom[0]]
-                m = getattr(AccessLogger, '_format_%s' % atom[0])
-                key_method = KeyMethod(format_key1, m)
-            else:
-                format_key2 = (self.LOG_FORMAT_MAP[atom[2]], atom[1])
-                m = getattr(AccessLogger, '_format_%s' % atom[2])
-                key_method = KeyMethod(format_key2,
-                                       functools.partial(m, atom[1]))
-
-            methods.append(key_method)
-
-        log_format = self.FORMAT_RE.sub(r'%s', log_format)
-        log_format = self.CLEANUP_RE.sub(r'%\1', log_format)
-        return log_format, methods
-
-    @staticmethod
-    def _format_i(key: str,
-                  request: 'BaseRequest',
-                  response: 'StreamResponse',
-                  time: float) -> str:
-        if request is None:
-            return '(no headers)'
-
-        # suboptimal, make istr(key) once
-        return request.headers.get(key, '-')
-
-    @staticmethod
-    def _format_o(key: str,
-                  request: 'BaseRequest',
-                  response: 'StreamResponse',
-                  time: float) -> str:
-        # suboptimal, make istr(key) once
-        return response.headers.get(key, '-')
-
-    @staticmethod
-    def _format_a(request: 'BaseRequest',
-                  response: 'StreamResponse',
-                  time: float) -> str:
-        if request is None:
-            return '-'
-        ip = request.remote
-        return ip if ip is not None else '-'
-
-    @staticmethod
-    def _format_t(request: 'BaseRequest',
-                  response: 'StreamResponse',
-                  time: float) -> str:
-        now = datetime.datetime.utcnow()
-        start_time = now - datetime.timedelta(seconds=time)
-        return start_time.strftime('[%d/%b/%Y:%H:%M:%S +0000]')
-
-    @staticmethod
-    def _format_P(request: 'BaseRequest',
-                  response: 'StreamResponse',
-                  time: float) -> str:
-        return "<%s>" % os.getpid()
-
-    @staticmethod
-    def _format_r(request: 'BaseRequest',
-                  response: 'StreamResponse',
-                  time: float) -> str:
-        if request is None:
-            return '-'
-        return '%s %s HTTP/%s.%s' % (request.method, request.path_qs,
-                                     request.version.major,
-                                     request.version.minor)
-
-    @staticmethod
-    def _format_s(request: 'BaseRequest',
-                  response: 'StreamResponse',
-                  time: float) -> str:
-        return response.status
-
-    @staticmethod
-    def _format_b(request: 'BaseRequest',
-                  response: 'StreamResponse',
-                  time: float) -> str:
-        return response.body_length
-
-    @staticmethod
-    def _format_T(request: 'BaseRequest',
-                  response: 'StreamResponse',
-                  time: float) -> str:
-        return str(round(time))
-
-    @staticmethod
-    def _format_Tf(request: 'BaseRequest',
-                   response: 'StreamResponse',
-                   time: float) -> str:
-        return '%06f' % time
-
-    @staticmethod
-    def _format_D(request: 'BaseRequest',
-                  response: 'StreamResponse',
-                  time: float) -> str:
-        return str(round(time * 1000000))
-
-    def _format_line(self,
-                     request: 'BaseRequest',
-                     response: 'StreamResponse',
-                     time: float) -> Iterable[Tuple[str,
-                                                    Callable[['BaseRequest',
-                                                              'StreamResponse',
-                                                              float],
-                                                             str]]]:
-        return [(key, method(request, response, time))
-                for key, method in self._methods]
-
-    def log(self,
-            request: 'BaseRequest',
-            response: 'StreamResponse',
-            time: float) -> None:
-        try:
-            fmt_info = self._format_line(request, response, time)
-
-            values = list()
-            extra = dict()
-            for key, value in fmt_info:
-                values.append(value)
-
-                if key.__class__ is str:
-                    extra[key] = value
-                else:
-                    k1, k2 = key
-                    dct = extra.get(k1, {})
-                    dct[k2] = value  # type: ignore
-                    extra[k1] = dct  # type: ignore
-
-            self.logger.info(self._log_format % tuple(values), extra=extra)
-        except Exception:
-            self.logger.exception("Error in logging")
-
-
 class reify:
     """Use as a class method decorator.  It operates almost exactly like
     the Python `@property` decorator, but it puts the result of the

aiohttp/web.py

@@ -6,13 +6,14 @@
 from collections.abc import Iterable
 from importlib import import_module
 
-from . import (helpers, web_app, web_exceptions, web_fileresponse,
-               web_middlewares, web_protocol, web_request, web_response,
-               web_routedef, web_runner, web_server, web_urldispatcher, web_ws)
+from . import (web_app, web_exceptions, web_fileresponse, web_middlewares,
+               web_protocol, web_request, web_response, web_routedef,
+               web_runner, web_server, web_urldispatcher, web_ws)
 from .log import access_logger
 from .web_app import *  # noqa
 from .web_exceptions import *  # noqa
 from .web_fileresponse import *  # noqa
+from .web_log import AccessLogger
 from .web_middlewares import *  # noqa
 from .web_protocol import *  # noqa
 from .web_request import *  # noqa
@@ -42,8 +43,8 @@
 
 def run_app(app, *, host=None, port=None, path=None, sock=None,
             shutdown_timeout=60.0, ssl_context=None,
-            print=print, backlog=128, access_log_class=helpers.AccessLogger,
-            access_log_format=helpers.AccessLogger.LOG_FORMAT,
+            print=print, backlog=128, access_log_class=AccessLogger,
+            access_log_format=AccessLogger.LOG_FORMAT,
             access_log=access_logger, handle_signals=True,
             reuse_address=None, reuse_port=None):
     """Run an app locally"""

aiohttp/web_app.py

@@ -9,9 +9,10 @@
 from . import hdrs
 from .abc import AbstractAccessLogger, AbstractMatchInfo, AbstractRouter
 from .frozenlist import FrozenList
-from .helpers import DEBUG, AccessLogger
+from .helpers import DEBUG
 from .log import web_logger
 from .signals import Signal
+from .web_log import AccessLogger
 from .web_middlewares import _fix_request_current_app
 from .web_request import Request
 from .web_response import StreamResponse