enhancement to AccessLogger

aiohttp/helpers.py

@@ -267,12 +267,29 @@ class AccessLogger:
         %{FOO}e  os.environ['FOO']
 
     """
+    LOG_FORMAT_MAP = {
+        'a': 'remote_address',
+        't': 'request_time',
+        'P': 'process_id',
+        'r': 'first_request_line',
+        's': 'response_status',
+        'b': 'response_size',
+        'O': 'bytes_sent',
+        'T': 'request_time',
+        'Tf': 'request_time_frac',
+        'D': 'request_time_micro',
+        'i': 'request_header',
+        'o': 'response_header',
+        'e': 'environ'
+    }
 
     LOG_FORMAT = '%a %l %u %t "%r" %s %b "%{Referrer}i" "%{User-Agent}i"'
     FORMAT_RE = re.compile(r'%(\{([A-Za-z0-9\-_]+)\}([ioe])|[atPrsbOD]|Tf?)')
     CLEANUP_RE = re.compile(r'(%[^s])')
     _FORMAT_CACHE = {}
 
+    KeyMethod = namedtuple('KeyMethod', 'key method')
+
     def __init__(self, logger, log_format=LOG_FORMAT):
         """Initialise the logger.
 
@@ -281,10 +298,12 @@ def __init__(self, logger, log_format=LOG_FORMAT):
 
         """
         self.logger = logger
+
         _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):
@@ -311,14 +330,22 @@ def compile_format(self, log_format):
 
         log_format = log_format.replace("%l", "-")
         log_format = log_format.replace("%u", "-")
-        methods = []
+
+        # 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] == '':
-                methods.append(getattr(AccessLogger, '_format_%s' % atom[0]))
+                format_key = self.LOG_FORMAT_MAP[atom[0]]
+                m = getattr(AccessLogger, '_format_%s' % atom[0])
             else:
+                format_key = (self.LOG_FORMAT_MAP[atom[2]], atom[1])
                 m = getattr(AccessLogger, '_format_%s' % atom[2])
-                methods.append(functools.partial(m, atom[1]))
+                m = functools.partial(m, atom[1])
+
+            methods.append(self.KeyMethod(format_key, m))
+
         log_format = self.FORMAT_RE.sub(r'%s', log_format)
         log_format = self.CLEANUP_RE.sub(r'%\1', log_format)
         return log_format, methods
@@ -331,6 +358,7 @@ def _format_e(key, args):
     def _format_i(key, args):
         if not args[0]:
             return '(no headers)'
+
         # suboptimal, make istr(key) once
         return args[0].headers.get(key, '-')
 
@@ -390,7 +418,7 @@ def _format_D(args):
         return round(args[4] * 1000000)
 
     def _format_line(self, args):
-        return tuple(m(args) for m in self._methods)
+        return ((key, method(args)) for key, method in self._methods)
 
     def log(self, message, environ, response, transport, time):
         """Log access.
@@ -402,8 +430,20 @@ def log(self, message, environ, response, transport, time):
         :param float time: Time taken to serve the request.
         """
         try:
-            self.logger.info(self._log_format % self._format_line(
-                [message, environ, response, transport, time]))
+            fmt_info = self._format_line(
+                [message, environ, response, transport, time])
+
+            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}
+
+            self.logger.info(self._log_format % tuple(values), extra=extra)
         except Exception:
             self.logger.exception("Error in logging")
 

aiohttp/web.py

@@ -293,7 +293,7 @@ def __repr__(self):
 
 def run_app(app, *, host='0.0.0.0', port=None,
             shutdown_timeout=60.0, ssl_context=None,
-            print=print, backlog=128):
+            print=print, backlog=128, access_log_format=None):
     """Run an app locally"""
     if port is None:
         if not ssl_context:
@@ -303,7 +303,10 @@ def run_app(app, *, host='0.0.0.0', port=None,
 
     loop = app.loop
 
-    handler = app.make_handler()
+    make_handler_kwargs = dict()
+    if access_log_format is not None:
+        make_handler_kwargs['access_log_format'] = access_log_format
+    handler = app.make_handler(**make_handler_kwargs)
     server = loop.create_server(handler, host, port, ssl=ssl_context,
                                 backlog=backlog)
     srv, startup_res = loop.run_until_complete(asyncio.gather(server,

setup.py

@@ -80,7 +80,7 @@ def run(self):
 args = dict(
     name='aiohttp',
     version=version,
-    description=('http client/server for asyncio'),
+    description='http client/server for asyncio',
     long_description='\n\n'.join((read('README.rst'), read('CHANGES.rst'))),
     classifiers=[
         'License :: OSI Approved :: Apache Software License',

tests/test_helpers.py

@@ -159,7 +159,19 @@ def test_access_logger_atoms(mocker):
     assert not mock_logger.exception.called
     expected = ('127.0.0.2 [01/Jan/1843:00:00:00 +0000] <42> - - '
                 'GET /path HTTP/1.1 200 42 123 3 3.141593 3141593')
-    mock_logger.info.assert_called_with(expected)
+    extra = {
+        'bytes_sent': 123,
+        'first_request_line': 'GET /path HTTP/1.1',
+        'process_id': '<42>',
+        'remote_address': '127.0.0.2',
+        'request_time': 3,
+        'request_time_frac': '3.141593',
+        'request_time_micro': 3141593,
+        'response_size': 42,
+        'response_status': 200
+    }
+
+    mock_logger.info.assert_called_with(expected, extra=extra)
 
 
 def test_access_logger_dicts():
@@ -174,7 +186,13 @@ def test_access_logger_dicts():
     access_logger.log(message, environ, response, transport, 0.0)
     assert not mock_logger.error.called
     expected = 'Mock/1.0 123 EGGS -'
-    mock_logger.info.assert_called_with(expected)
+    extra = {
+        'environ': {'SPAM': 'EGGS'},
+        'request_header': {'None': '-'},
+        'response_header': {'Content-Length': 123}
+    }
+
+    mock_logger.info.assert_called_with(expected, extra=extra)
 
 
 def test_access_logger_unix_socket():
@@ -189,7 +207,7 @@ def test_access_logger_unix_socket():
     access_logger.log(message, environ, response, transport, 0.0)
     assert not mock_logger.error.called
     expected = '||'
-    mock_logger.info.assert_called_with(expected)
+    mock_logger.info.assert_called_with(expected, extra={'remote_address': ''})
 
 
 def test_logger_no_message_and_environ():
@@ -198,8 +216,14 @@ def test_logger_no_message_and_environ():
     mock_transport.get_extra_info.return_value = ("127.0.0.3", 0)
     access_logger = helpers.AccessLogger(mock_logger,
                                          "%r %{FOOBAR}e %{content-type}i")
+    extra_dict = {
+        'environ': {'FOOBAR': '-'},
+        'first_request_line': '-',
+        'request_header': {'content-type': '(no headers)'}
+    }
+
     access_logger.log(None, None, None, mock_transport, 0.0)
-    mock_logger.info.assert_called_with("- - (no headers)")
+    mock_logger.info.assert_called_with("- - (no headers)", extra=extra_dict)
 
 
 def test_logger_internal_error():
@@ -215,7 +239,7 @@ def test_logger_no_transport():
     mock_logger = mock.Mock()
     access_logger = helpers.AccessLogger(mock_logger, "%a")
     access_logger.log(None, None, None, None, 0)
-    mock_logger.info.assert_called_with("-")
+    mock_logger.info.assert_called_with("-", extra={'remote_address': '-'})
 
 
 # ----------------------------------------------------------

tests/test_run_app.py

@@ -19,6 +19,22 @@ def test_run_app_http(loop, mocker):
     app.startup.assert_called_once_with()
 
 
+def test_run_app_http_access_format(loop, mocker):
+    mocker.spy(loop, 'create_server')
+    loop.call_later(0.05, loop.stop)
+
+    app = web.Application(loop=loop)
+    mocker.spy(app, 'startup')
+
+    web.run_app(app, print=lambda *args: None, access_log_format='%a')
+
+    assert loop.is_closed()
+    cs = loop.create_server
+    cs.assert_called_with(mock.ANY, '0.0.0.0', 8080, ssl=None, backlog=128)
+    assert cs.call_args[0][0]._kwargs['access_log_format'] == '%a'
+    app.startup.assert_called_once_with()
+
+
 def test_run_app_https(loop, mocker):
     mocker.spy(loop, 'create_server')
     loop.call_later(0.05, loop.stop)