Support swift.proxy_logging_status in request env

When logging a request, if the request environ has a
swift.proxy_logging_status item then use its value for the log
message status int.

The swift.proxy_logging_status hint may be used by other middlewares
when the desired logged status is different from the wire_status_int.

If the proxy_logging middleware detects a client disconnect then any
swift.proxy_logging_status item is ignored and a 499 status int is
logged, as per current behaviour. i.e.:

  * client disconnect overrides swift.proxy_logging_status and the
    response status
  * swift.proxy_logging_status overrides the response status

If the proxy_logging middleware catches an exception then the logged
status int will be 500 regardless of any swift.proxy_logging_status
item.

Co-Authored-By: Alistair Coles <alistairncoles@gmail.com>
Change-Id: I9b5cc6d5fb69a2957b8c4846ce1feed8c115e6b6

doc/source/development_middleware.rst

@@ -198,6 +198,13 @@ filter factory::
         return webhook_filter
 
 
+Middlewares can override the status integer that is logged by proxy_logging
+middleware by setting ``swift.proxy_logging_status`` in the request WSGI
+environment. The value should be an integer. The value will replace the default
+status integer in the log message, unless the proxy_logging middleware detects
+a client disconnect or exception while handling the request, in which case
+``swift.proxy_logging_status`` is overridden by a 499 or 500 respectively.
+
 --------------
 Swift Metadata
 --------------

swift/common/middleware/proxy_logging.py

@@ -27,19 +27,28 @@ The logging format implemented below is as follows::
         start_time end_time policy_index
 
 These values are space-separated, and each is url-encoded, so that they can
-be separated with a simple .split()
+be separated with a simple ``.split()``.
 
-* remote_addr is the contents of the REMOTE_ADDR environment variable, while
-  client_ip is swift's best guess at the end-user IP, extracted variously
-  from the X-Forwarded-For header, X-Cluster-Ip header, or the REMOTE_ADDR
-  environment variable.
+* ``remote_addr`` is the contents of the REMOTE_ADDR environment variable,
+  while ``client_ip`` is swift's best guess at the end-user IP, extracted
+  variously from the X-Forwarded-For header, X-Cluster-Ip header, or the
+  REMOTE_ADDR environment variable.
 
-* source (swift.source in the WSGI environment) indicates the code
+* ``status_int`` is the integer part of the ``status`` string passed to this
+  middleware's start_response function, unless the WSGI environment has an item
+  with key ``swift.proxy_logging_status``, in which case the value of that item
+  is used. Other middleware's may set ``swift.proxy_logging_status`` to
+  override the logging of ``status_int``. In either case, the logged
+  ``status_int`` value is forced to 499 if a client disconnect is detected
+  while this middleware is handling a request, or 500 if an exception is caught
+  while handling a request.
+
+* ``source`` (``swift.source`` in the WSGI environment) indicates the code
   that generated the request, such as most middleware. (See below for
   more detail.)
 
-* log_info (swift.log_info in the WSGI environment) is for additional
-  information that could prove quite useful, such as any x-delete-at
+* ``log_info`` (``swift.log_info`` in the WSGI environment) is for additional
+  information that could prove quite useful, such as any ``x-delete-at``
   value or other "behind the scenes" activity that might not
   otherwise be detectable from the plain log information. Code that
   wishes to add additional log information should use code like
@@ -62,18 +71,18 @@ For example, with staticweb, the middleware might intercept a request to
 /v1/AUTH_acc/cont/, make a subrequest to the proxy to retrieve
 /v1/AUTH_acc/cont/index.html and, in effect, respond to the client's original
 request using the 2nd request's body. In this instance the subrequest will be
-logged by the rightmost middleware (with a swift.source set) and the outgoing
-request (with body overridden) will be logged by leftmost middleware.
+logged by the rightmost middleware (with a ``swift.source`` set) and the
+outgoing request (with body overridden) will be logged by leftmost middleware.
 
 Requests that follow the normal pipeline (use the same wsgi environment
 throughout) will not be double logged because an environment variable
-(swift.proxy_access_log_made) is checked/set when a log is made.
+(``swift.proxy_access_log_made``) is checked/set when a log is made.
 
-All middleware making subrequests should take care to set swift.source when
+All middleware making subrequests should take care to set ``swift.source`` when
 needed. With the doubled proxy logs, any consumer/processor of swift's proxy
-logs should look at the swift.source field, the rightmost log value, to decide
-if this is a middleware subrequest or not. A log processor calculating
-bandwidth usage will want to only sum up logs with no swift.source.
+logs should look at the ``swift.source`` field, the rightmost log value, to
+decide if this is a middleware subrequest or not. A log processor calculating
+bandwidth usage will want to only sum up logs with no ``swift.source``.
 """
 
 import os
@@ -389,11 +398,11 @@ class ProxyLoggingMiddleware(object):
         def my_start_response(status, headers, exc_info=None):
             start_response_args[0] = (status, list(headers), exc_info)
 
-        def status_int_for_logging(start_status, client_disconnect=False):
+        def status_int_for_logging():
             # log disconnected clients as '499' status code
-            if client_disconnect or input_proxy.client_disconnect:
+            if input_proxy.client_disconnect:
                 return 499
-            return start_status
+            return env.get('swift.proxy_logging_status')
 
         def iter_response(iterable):
             iterator = reiterate(iterable)
@@ -438,21 +447,19 @@ class ProxyLoggingMiddleware(object):
                         metric_name_policy + '.first-byte.timing', ttfb * 1000)
 
             bytes_sent = 0
-            client_disconnect = False
-            start_status = wire_status_int
             try:
                 for chunk in iterator:
                     bytes_sent += len(chunk)
                     yield chunk
             except GeneratorExit:  # generator was closed before we finished
-                client_disconnect = True
+                env['swift.proxy_logging_status'] = 499
                 raise
             except Exception:
-                start_status = 500
+                env['swift.proxy_logging_status'] = 500
                 raise
             finally:
-                status_int = status_int_for_logging(
-                    start_status, client_disconnect)
+                env.setdefault('swift.proxy_logging_status', wire_status_int)
+                status_int = status_int_for_logging()
                 self.log_request(
                     req, status_int, input_proxy.bytes_received, bytes_sent,
                     start_time, time.time(), resp_headers=resp_headers,
@@ -463,7 +470,8 @@ class ProxyLoggingMiddleware(object):
             iterable = self.app(env, my_start_response)
         except Exception:
             req = Request(env)
-            status_int = status_int_for_logging(500)
+            env['swift.proxy_logging_status'] = 500
+            status_int = status_int_for_logging()
             self.log_request(
                 req, status_int, input_proxy.bytes_received, 0, start_time,
                 time.time())

test/unit/common/middleware/test_proxy_logging.py

@@ -36,7 +36,7 @@ from test.unit.common.middleware.helpers import FakeAppThatExcepts
 class FakeApp(object):
 
     def __init__(self, body=None, response_str='200 OK', policy_idx='0',
-                 chunked=False):
+                 chunked=False, environ_updates=None):
         if body is None:
             body = [b'FAKE APP']
         elif isinstance(body, six.binary_type):
@@ -46,6 +46,7 @@ class FakeApp(object):
         self.response_str = response_str
         self.policy_idx = policy_idx
         self.chunked = chunked
+        self.environ_updates = environ_updates or {}
 
     def __call__(self, env, start_response):
         try:
@@ -65,7 +66,7 @@ class FakeApp(object):
         if is_container_or_object_req and self.policy_idx is not None:
             headers.append(('X-Backend-Storage-Policy-Index',
                            str(self.policy_idx)))
-
+        env.update(self.environ_updates)
         start_response(self.response_str, headers)
         while env['wsgi.input'].read(5):
             pass
@@ -791,6 +792,136 @@ class TestProxyLogging(unittest.TestCase):
         self.assertEqual(log_parts[6], '499')
         self.assertEqual(log_parts[10], '-')  # read length
 
+    def test_environ_has_proxy_logging_status(self):
+        conf = {'log_msg_template':
+                '{method} {path} {status_int} {wire_status_int}'}
+
+        def do_test(environ_updates):
+            fake_app = FakeApp(body=[b'Slow Down'],
+                               response_str='503 Slow Down',
+                               environ_updates=environ_updates)
+            app = proxy_logging.ProxyLoggingMiddleware(fake_app, conf)
+            app.access_logger = debug_logger()
+            req = Request.blank('/v1/a/c')
+            captured_start_resp = mock.MagicMock()
+            try:
+                resp = app(req.environ, captured_start_resp)
+                b''.join(resp)  # read body
+            except IOError:
+                pass
+            captured_start_resp.assert_called_once_with(
+                '503 Slow Down', mock.ANY, None)
+            return self._log_parts(app)
+
+        # control case, logged status == wire status
+        environ_updates = {}
+        self.assertEqual(do_test(environ_updates),
+                         ['GET', '/v1/a/c', '503', '503'])
+
+        # logged status is forced to other value
+        environ_updates = {'swift.proxy_logging_status': 429}
+        self.assertEqual(do_test(environ_updates),
+                         ['GET', '/v1/a/c', '429', '503'])
+
+        environ_updates = {'swift.proxy_logging_status': '429'}
+        self.assertEqual(do_test(environ_updates),
+                         ['GET', '/v1/a/c', '429', '503'])
+
+        environ_updates = {'swift.proxy_logging_status': None}
+        self.assertEqual(do_test(environ_updates),
+                         ['GET', '/v1/a/c', '-', '503'])
+
+        environ_updates = {'swift.proxy_logging_status': ''}
+        self.assertEqual(do_test(environ_updates),
+                         ['GET', '/v1/a/c', '-', '503'])
+
+    def test_environ_has_proxy_logging_status_unread_body(self):
+        conf = {'log_msg_template':
+                '{method} {path} {status_int} {wire_status_int}'}
+
+        def do_test(environ_updates):
+            fake_app = FakeApp(body=[b'Slow Down'],
+                               response_str='503 Slow Down',
+                               environ_updates=environ_updates)
+            app = proxy_logging.ProxyLoggingMiddleware(fake_app, conf)
+            app.access_logger = debug_logger()
+            req = Request.blank('/v1/a/c')
+            captured_start_resp = mock.MagicMock()
+            resp = app(req.environ, captured_start_resp)
+            # read first chunk
+            next(resp)
+            resp.close()  # raise a GeneratorExit in middleware app_iter loop
+            captured_start_resp.assert_called_once_with(
+                '503 Slow Down', mock.ANY, None)
+            return self._log_parts(app)
+
+        # control case, logged status is 499
+        environ_updates = {}
+        self.assertEqual(do_test(environ_updates),
+                         ['GET', '/v1/a/c', '499', '503'])
+
+        # logged status is forced to 499 despite swift.proxy_logging_status
+        environ_updates = {'swift.proxy_logging_status': '429'}
+        self.assertEqual(do_test(environ_updates),
+                         ['GET', '/v1/a/c', '499', '503'])
+
+    def test_environ_has_proxy_logging_status_and_app_explodes(self):
+        # verify exception overrides proxy_logging_status
+        conf = {'log_msg_template':
+                '{method} {path} {status_int} {wire_status_int}'}
+
+        class ExplodingFakeApp(object):
+
+            def __call__(self, env, start_response):
+                # this is going to be so great!
+                env['swift.proxy_logging_status'] = '456'
+                start_response('568 Bespoke', [('X-Special', 'fun')])
+                raise Exception('oops!')
+
+        fake_app = ExplodingFakeApp()
+        app = proxy_logging.ProxyLoggingMiddleware(fake_app, conf)
+        app.access_logger = debug_logger()
+        req = Request.blank('/v1/a/c')
+        captured_start_resp = mock.MagicMock()
+        with self.assertRaises(Exception) as cm:
+            app(req.environ, captured_start_resp)
+        captured_start_resp.assert_not_called()
+        self.assertEqual('oops!', str(cm.exception))
+        self.assertEqual(self._log_parts(app),
+                         ['GET', '/v1/a/c', '500', '500'])
+
+    def test_environ_has_proxy_logging_status_and_body_explodes(self):
+        # verify exception overrides proxy_logging_status
+        conf = {'log_msg_template':
+                '{method} {path} {status_int} {wire_status_int}'}
+
+        def exploding_body():
+            yield 'some'
+            yield 'stuff'
+            raise Exception('oops!')
+
+        class ExplodingFakeApp(object):
+
+            def __call__(self, env, start_response):
+                # this is going to be so great!
+                env['swift.proxy_logging_status'] = '456'
+                start_response('568 Bespoke', [('X-Special', 'fun')])
+                return exploding_body()
+
+        fake_app = ExplodingFakeApp()
+        app = proxy_logging.ProxyLoggingMiddleware(fake_app, conf)
+        app.access_logger = debug_logger()
+        req = Request.blank('/v1/a/c')
+        captured_start_resp = mock.MagicMock()
+        app_iter = app(req.environ, captured_start_resp)
+        with self.assertRaises(Exception) as cm:
+            b''.join(app_iter)
+        captured_start_resp.assert_called_once_with(
+            '568 Bespoke', [('X-Special', 'fun')], None)
+        self.assertEqual('oops!', str(cm.exception))
+        self.assertEqual(self._log_parts(app),
+                         ['GET', '/v1/a/c', '500', '568'])
+
     def test_app_exception(self):
         app = proxy_logging.ProxyLoggingMiddleware(
             FakeAppThatExcepts(), {})