Access logger improvements (#2145)

* Fix #2123: User request instead of message in access logger

* Doc update

* Optimize request.host property

* Introduce BaseRequest.remote property

* Fix spelling errors

* Add tests

Author: asvetlov

aiohttp/hdrs.py

@@ -91,5 +91,6 @@
 WANT_DIGEST = istr('WANT-DIGEST')
 WARNING = istr('WARNING')
 WWW_AUTHENTICATE = istr('WWW-AUTHENTICATE')
+X_FORWARDED_FOR = istr('X-FORWARDED-FOR')
 X_FORWARDED_HOST = istr('X-FORWARDED-HOST')
 X_FORWARDED_PROTO = istr('X-FORWARDED-PROTO')

aiohttp/helpers.py

@@ -306,7 +306,7 @@ class AccessLogger:
         log = logging.getLogger("spam")
         log_format = "%a %{User-Agent}i"
         access_logger = AccessLogger(log, log_format)
-        access_logger.log(message, environ, response, transport, time)
+        access_logger.log(request, response, time)
 
     Format:
         %%  The percent sign
@@ -337,7 +337,6 @@ class AccessLogger:
         '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"'
@@ -408,76 +407,65 @@ def compile_format(self, log_format):
         return log_format, methods
 
     @staticmethod
-    def _format_e(key, args):
-        return (args[1] or {}).get(key, '-')
-
-    @staticmethod
-    def _format_i(key, args):
-        if not args[0]:
+    def _format_i(key, request, response, time):
+        if request is None:
             return '(no headers)'
 
         # suboptimal, make istr(key) once
-        return args[0].headers.get(key, '-')
+        return request.headers.get(key, '-')
 
     @staticmethod
-    def _format_o(key, args):
+    def _format_o(key, request, response, time):
         # suboptimal, make istr(key) once
-        return args[2].headers.get(key, '-')
+        return response.headers.get(key, '-')
 
     @staticmethod
-    def _format_a(args):
-        if args[3] is None:
+    def _format_a(request, response, time):
+        if request is None:
             return '-'
-        peername = args[3].get_extra_info('peername')
-        if isinstance(peername, (list, tuple)):
-            return peername[0]
-        else:
-            return peername
+        ip = request.remote
+        return ip if ip is not None else '-'
 
     @staticmethod
-    def _format_t(args):
+    def _format_t(request, response, time):
         return datetime.datetime.utcnow().strftime('[%d/%b/%Y:%H:%M:%S +0000]')
 
     @staticmethod
-    def _format_P(args):
+    def _format_P(request, response, time):
         return "<%s>" % os.getpid()
 
     @staticmethod
-    def _format_r(args):
-        msg = args[0]
-        if not msg:
+    def _format_r(request, response, time):
+        if request is None:
             return '-'
-        return '%s %s HTTP/%s.%s' % tuple((msg.method,
-                                           msg.path) + msg.version)
-
-    @staticmethod
-    def _format_s(args):
-        return args[2].status
+        return '%s %s HTTP/%s.%s' % tuple((request.method,
+                                           request.path_qs) + request.version)
 
     @staticmethod
-    def _format_b(args):
-        return args[2].body_length
+    def _format_s(request, response, time):
+        return response.status
 
     @staticmethod
-    def _format_O(args):
-        return args[2].body_length
+    def _format_b(request, response, time):
+        return response.body_length
 
     @staticmethod
-    def _format_T(args):
-        return round(args[4])
+    def _format_T(request, response, time):
+        return round(time)
 
     @staticmethod
-    def _format_Tf(args):
-        return '%06f' % args[4]
+    def _format_Tf(request, response, time):
+        return '%06f' % time
 
     @staticmethod
-    def _format_D(args):
-        return round(args[4] * 1000000)
+    def _format_D(request, response, time):
+        return round(time * 1000000)
 
-    def _format_line(self, args):
-        return ((key, method(args)) for key, method in self._methods)
+    def _format_line(self, request, response, time):
+        return ((key, method(request, response, time))
+                for key, method in self._methods)
 
-    def log(self, message, environ, response, transport, time):
+    def log(self, request, response, time):
         """Log access.
 
         :param message: Request object. May be None.
@@ -487,8 +475,7 @@ def log(self, message, environ, response, transport, time):
         :param float time: Time taken to serve the request.
         """
         try:
-            fmt_info = self._format_line(
-                [message, environ, response, transport, time])
+            fmt_info = self._format_line(request, response, time)
 
             values = list()
             extra = dict()

aiohttp/web_protocol.py

@@ -349,10 +349,9 @@ def force_close(self, send_last_heartbeat=False):
             self.transport.close()
             self.transport = None
 
-    def log_access(self, message, environ, response, time):
-        if self.access_logger:
-            self.access_logger.log(message, environ, response,
-                                   self.transport, time)
+    def log_access(self, request, response, time):
+        if self.access_logger is not None:
+            self.access_logger.log(request, response, time)
 
     def log_debug(self, *args, **kw):
         if self.debug:
@@ -444,7 +443,7 @@ def start(self, message, payload, handler):
 
                 # log access
                 if self.access_log:
-                    self.log_access(message, None, resp, loop.time() - now)
+                    self.log_access(request, resp, loop.time() - now)
 
                 # check payload
                 if not payload.is_eof():

aiohttp/web_request.py

@@ -275,7 +275,7 @@ def version(self):
 
     @reify
     def host(self):
-        """ Hostname of the request.
+        """Hostname of the request.
 
         Hostname is resolved through the following headers, in this order:
 
@@ -288,12 +288,38 @@ def host(self):
         host = next(
             (f['host'] for f in self.forwarded if 'host' in f), None
         )
-        if not host and hdrs.X_FORWARDED_HOST in self._message.headers:
-            host = self._message.headers[hdrs.X_FORWARDED_HOST]
-        elif hdrs.HOST in self._message.headers:
-            host = self._message.headers[hdrs.HOST]
+        if host is None:
+            host = self._message.headers.get(hdrs.X_FORWARDED_HOST)
+        if host is None:
+            host = self._message.headers.get(hdrs.HOST)
         return host
 
+    @reify
+    def remote(self):
+        """Remote IP of client initiated HTTP request.
+
+        The IP is resolved through the following headers, in this order:
+
+        - Forwarded
+        - X-Forwarded-For
+        - peername of opened socket
+        """
+        ip = next(
+            (f['for'] for f in self.forwarded if 'for' in f), None
+        )
+        if ip is None:
+            ips = self._message.headers.get(hdrs.X_FORWARDED_FOR)
+            if ips is not None:
+                ip = ips.split(',')[0].strip()
+        if ip is None:
+            transport = self._transport
+            peername = transport.get_extra_info('peername')
+            if isinstance(peername, (list, tuple)):
+                ip = peername[0]
+            else:
+                ip = peername
+        return ip
+
     @reify
     def url(self):
         return URL('{}://{}{}'.format(self._scheme,

changes/2123.feature

@@ -0,0 +1,4 @@
+Use request for getting access log information instead of message/transport pair.
+
+Add `RequestBase.remote` property for accessing to IP of client
+initiated HTTP request.

changes/2123.removal

@@ -0,0 +1,4 @@
+Drop %O format from logging, use %b instead.
+
+Drop %e format from logging, environment variables are not supported anymore.
+

docs/logging.rst

@@ -71,8 +71,6 @@ request and response:
 +--------------+---------------------------------------------------------+
 | ``%b``       | Size of response in bytes, excluding HTTP headers       |
 +--------------+---------------------------------------------------------+
-| ``%O``       | Bytes sent, including headers                           |
-+--------------+---------------------------------------------------------+
 | ``%T``       | The time taken to serve the request, in seconds         |
 +--------------+---------------------------------------------------------+
 | ``%Tf``      | The time taken to serve the request, in seconds         |
@@ -84,8 +82,6 @@ request and response:
 +--------------+---------------------------------------------------------+
 | ``%{FOO}o``  | ``response.headers['FOO']``                             |
 +--------------+---------------------------------------------------------+
-| ``%{FOO}e``  | ``os.environ['FOO']``                                   |
-+--------------+---------------------------------------------------------+
 
 Default access log format is::
 

docs/spelling_wordlist.txt

@@ -156,6 +156,7 @@ Paolini
 param
 params
 pathlib
+peername
 ping
 pipelining
 pluggable

docs/web_reference.rst

@@ -126,6 +126,21 @@ and :ref:`aiohttp-web-signals` handlers.
       Returns  :class:`str`, or ``None`` if no host name is found in the
       headers.
 
+   .. attribute:: remote
+
+      Originating IP address of a client initiated HTTP request.
+
+      The IP is resolved through the following headers, in this order:
+
+      - *Forwarded*
+      - *X-Forwarded-For*
+      - peer name of opened socket
+
+      Returns :class:`str`, or ``None`` if no remote IP information is
+      provided.
+
+      .. versionadded:: 2.3
+
    .. attribute:: path_qs
 
       The URL including PATH_INFO and the query string. e.g.,

tests/test_helpers.py

@@ -131,10 +131,10 @@ def test_basic_auth_decode_bad_base64():
 
 
 def test_access_logger_format():
-    log_format = '%T {%{SPAM}e} "%{ETag}o" %X {X} %%P %{FOO_TEST}e %{FOO1}e'
+    log_format = '%T "%{ETag}o" %X {X} %%P'
     mock_logger = mock.Mock()
     access_logger = helpers.AccessLogger(mock_logger, log_format)
-    expected = '%s {%s} "%s" %%X {X} %%%s %s %s'
+    expected = '%s "%s" %%X {X} %%%s'
     assert expected == access_logger._log_format
 
 
@@ -147,12 +147,11 @@ def test_access_logger_atoms(mocker):
     log_format = '%a %t %P %l %u %r %s %b %T %Tf %D'
     mock_logger = mock.Mock()
     access_logger = helpers.AccessLogger(mock_logger, log_format)
-    message = mock.Mock(headers={}, method="GET", path="/path", version=(1, 1))
-    environ = {}
+    request = mock.Mock(headers={}, method="GET", path_qs="/path",
+                        version=(1, 1),
+                        remote="127.0.0.2")
     response = mock.Mock(headers={}, body_length=42, status=200)
-    transport = mock.Mock()
-    transport.get_extra_info.return_value = ("127.0.0.2", 1234)
-    access_logger.log(message, environ, response, transport, 3.1415926)
+    access_logger.log(request, response, 3.1415926)
     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 3 3.141593 3141593')
@@ -171,19 +170,16 @@ def test_access_logger_atoms(mocker):
 
 
 def test_access_logger_dicts():
-    log_format = '%{User-Agent}i %{Content-Length}o %{SPAM}e %{None}i'
+    log_format = '%{User-Agent}i %{Content-Length}o %{None}i'
     mock_logger = mock.Mock()
     access_logger = helpers.AccessLogger(mock_logger, log_format)
-    message = mock.Mock(headers={"User-Agent": "Mock/1.0"}, version=(1, 1))
-    environ = {"SPAM": "EGGS"}
+    request = mock.Mock(headers={"User-Agent": "Mock/1.0"}, version=(1, 1),
+                        remote="127.0.0.2")
     response = mock.Mock(headers={"Content-Length": 123})
-    transport = mock.Mock()
-    transport.get_extra_info.return_value = ("127.0.0.2", 1234)
-    access_logger.log(message, environ, response, transport, 0.0)
+    access_logger.log(request, response, 0.0)
     assert not mock_logger.error.called
-    expected = 'Mock/1.0 123 EGGS -'
+    expected = 'Mock/1.0 123 -'
     extra = {
-        'environ': {'SPAM': 'EGGS'},
         'request_header': {'None': '-'},
         'response_header': {'Content-Length': 123}
     }
@@ -195,46 +191,39 @@ def test_access_logger_unix_socket():
     log_format = '|%a|'
     mock_logger = mock.Mock()
     access_logger = helpers.AccessLogger(mock_logger, log_format)
-    message = mock.Mock(headers={"User-Agent": "Mock/1.0"}, version=(1, 1))
-    environ = {}
+    request = mock.Mock(headers={"User-Agent": "Mock/1.0"}, version=(1, 1),
+                        remote="")
     response = mock.Mock()
-    transport = mock.Mock()
-    transport.get_extra_info.return_value = ""
-    access_logger.log(message, environ, response, transport, 0.0)
+    access_logger.log(request, response, 0.0)
     assert not mock_logger.error.called
     expected = '||'
     mock_logger.info.assert_called_with(expected, extra={'remote_address': ''})
 
 
-def test_logger_no_message_and_environ():
+def test_logger_no_message():
     mock_logger = mock.Mock()
-    mock_transport = mock.Mock()
-    mock_transport.get_extra_info.return_value = ("127.0.0.3", 0)
     access_logger = helpers.AccessLogger(mock_logger,
-                                         "%r %{FOOBAR}e %{content-type}i")
+                                         "%r %{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)", extra=extra_dict)
+    access_logger.log(None, None, 0.0)
+    mock_logger.info.assert_called_with("- (no headers)", extra=extra_dict)
 
 
 def test_logger_internal_error():
     mock_logger = mock.Mock()
-    mock_transport = mock.Mock()
-    mock_transport.get_extra_info.return_value = ("127.0.0.3", 0)
     access_logger = helpers.AccessLogger(mock_logger, "%D")
-    access_logger.log(None, None, None, mock_transport, 'invalid')
+    access_logger.log(None, None, 'invalid')
     mock_logger.exception.assert_called_with("Error in logging")
 
 
 def test_logger_no_transport():
     mock_logger = mock.Mock()
     access_logger = helpers.AccessLogger(mock_logger, "%a")
-    access_logger.log(None, None, None, None, 0)
+    access_logger.log(None, None, 0)
     mock_logger.info.assert_called_with("-", extra={'remote_address': '-'})