From 31b994560332ffa22fbe45e43471db360467434c Mon Sep 17 00:00:00 2001
From: Peter Portante <peter.portante@redhat.com>
Date: Tue, 25 Mar 2014 15:56:44 -0400
Subject: [PATCH] Invert which proxy logging middleware instance logs
Prior to this patch the proxy_logging middleware always prepared to
read the response and process it for access logging, where the
proxy_logging instance first to handle the response bytes marked the
request as "logged".
This meant that the proxy_logging instance immediately before the
proxy-server app (right most in the pipeline, if properly setup) would
always log the responses for all the client requests, regardless if
middleware to the left of it still had processing to do for the
response. This would break SLO, where the slo middleware passed along
the GET of the manifest, unchanged from the client, so that the right
most proxy logging middleware would log the sponse for just the
manifest, but then the slo middleware would fetch all the segments of
the manifest, feeding them out in the response to the client, the
request now marked as "logged" so that the left most proxy logging
middleware would not log it.
This patch inverts this behavior so that now the first proxy_logging
middleware instance to receive a request in the pipeline marks that
request as handling it. So now, the left most proxy_logging middleware
handles logging for all client reaquests, and the right most
proxy_logging middleware handles all other requests initiated from
within the pipeline to its left.
Closes bug: 1297438
Change-Id: Ia3561523db76c693e4e0b2c38f461544dfcee086
---
swift/common/middleware/proxy_logging.py | 18 ++--
.../common/middleware/test_proxy_logging.py | 83 ++++++++++++++++++-
2 files changed, 92 insertions(+), 9 deletions(-)
diff --git a/swift/common/middleware/proxy_logging.py b/swift/common/middleware/proxy_logging.py
index e3b3b89ae9..0732700622 100644
--- a/swift/common/middleware/proxy_logging.py
+++ b/swift/common/middleware/proxy_logging.py
@@ -124,11 +124,11 @@ class ProxyLoggingMiddleware(object):
def method_from_req(self, req):
return req.environ.get('swift.orig_req_method', req.method)
- def req_already_logged(self, req):
- return req.environ.get('swift.proxy_access_log_made')
+ def req_already_logged(self, env):
+ return env.get('swift.proxy_access_log_made')
- def mark_req_logged(self, req):
- req.environ['swift.proxy_access_log_made'] = True
+ def mark_req_logged(self, env):
+ env['swift.proxy_access_log_made'] = True
def obscure_sensitive(self, value):
if value and len(value) > self.reveal_sensitive_prefix:
@@ -147,8 +147,6 @@ class ProxyLoggingMiddleware(object):
:param start_time: timestamp request started
:param end_time: timestamp request completed
"""
- if self.req_already_logged(req):
- return
req_path = get_valid_utf8_str(req.path)
the_request = quote(unquote(req_path), QUOTE_SAFE)
if req.query_string:
@@ -193,7 +191,6 @@ class ProxyLoggingMiddleware(object):
start_time_str,
end_time_str
)))
- self.mark_req_logged(req)
# Log timing and bytes-transfered data to StatsD
metric_name = self.statsd_metric_name(req, status_int, method)
# Only log data for valid controllers (or SOS) to keep the metric count
@@ -220,6 +217,11 @@ class ProxyLoggingMiddleware(object):
return '.'.join((stat_type, stat_method, str(status_int)))
def __call__(self, env, start_response):
+ if self.req_already_logged(env):
+ return self.app(env, start_response)
+
+ self.mark_req_logged(env)
+
start_response_args = [None]
input_proxy = InputProxy(env['wsgi.input'])
env['wsgi.input'] = input_proxy
@@ -261,7 +263,7 @@ class ProxyLoggingMiddleware(object):
# Log timing information for time-to-first-byte (GET requests only)
method = self.method_from_req(req)
- if method == 'GET' and not self.req_already_logged(req):
+ if method == 'GET':
status_int = status_int_for_logging()
metric_name = self.statsd_metric_name(req, status_int, method)
if metric_name:
diff --git a/test/unit/common/middleware/test_proxy_logging.py b/test/unit/common/middleware/test_proxy_logging.py
index 7e0744a4be..c577fd07e0 100644
--- a/test/unit/common/middleware/test_proxy_logging.py
+++ b/test/unit/common/middleware/test_proxy_logging.py
@@ -22,7 +22,7 @@ import mock
from test.unit import FakeLogger
from swift.common.utils import get_logger
from swift.common.middleware import proxy_logging
-from swift.common.swob import Request
+from swift.common.swob import Request, Response
class FakeApp(object):
@@ -757,6 +757,87 @@ class TestProxyLogging(unittest.TestCase):
self.assertEquals(log_parts[18], '10000000.000000000')
self.assertEquals(log_parts[19], '10000001.000000000')
+ def test_dual_logging_middlewares(self):
+ # Since no internal request is being made, outer most proxy logging
+ # middleware, log1, should have performed the logging.
+ app = FakeApp()
+ flg0 = FakeLogger()
+ env = {}
+ log0 = proxy_logging.ProxyLoggingMiddleware(app, env, logger=flg0)
+ flg1 = FakeLogger()
+ log1 = proxy_logging.ProxyLoggingMiddleware(log0, env, logger=flg1)
+
+ req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
+ resp = log1(req.environ, start_response)
+ resp_body = ''.join(resp)
+ self._log_parts(log0, should_be_empty=True)
+ log_parts = self._log_parts(log1)
+ self.assertEquals(log_parts[3], 'GET')
+ self.assertEquals(log_parts[4], '/')
+ self.assertEquals(log_parts[5], 'HTTP/1.0')
+ self.assertEquals(log_parts[6], '200')
+ self.assertEquals(resp_body, 'FAKE APP')
+ self.assertEquals(log_parts[11], str(len(resp_body)))
+
+ def test_dual_logging_middlewares_w_inner(self):
+
+ class FakeMiddleware(object):
+ """
+ Fake middleware to make a separate internal request, but construct
+ the response with different data.
+ """
+ def __init__(self, app, conf):
+ self.app = app
+ self.conf = conf
+
+ def GET(self, req):
+ # Make the internal request
+ ireq = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
+ resp = self.app(ireq.environ, start_response)
+ resp_body = ''.join(resp)
+ if resp_body != 'FAKE APP':
+ return Response(request=req,
+ body="FAKE APP WAS NOT RETURNED",
+ content_type="text/plain")
+ # But our response is different
+ return Response(request=req, body="FAKE MIDDLEWARE",
+ content_type="text/plain")
+
+ def __call__(self, env, start_response):
+ req = Request(env)
+ return self.GET(req)(env, start_response)
+
+ # Since an internal request is being made, inner most proxy logging
+ # middleware, log0, should have performed the logging.
+ app = FakeApp()
+ flg0 = FakeLogger()
+ env = {}
+ log0 = proxy_logging.ProxyLoggingMiddleware(app, env, logger=flg0)
+ fake = FakeMiddleware(log0, env)
+ flg1 = FakeLogger()
+ log1 = proxy_logging.ProxyLoggingMiddleware(fake, env, logger=flg1)
+
+ req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
+ resp = log1(req.environ, start_response)
+ resp_body = ''.join(resp)
+
+ # Inner most logger should have logged the app's response
+ log_parts = self._log_parts(log0)
+ self.assertEquals(log_parts[3], 'GET')
+ self.assertEquals(log_parts[4], '/')
+ self.assertEquals(log_parts[5], 'HTTP/1.0')
+ self.assertEquals(log_parts[6], '200')
+ self.assertEquals(log_parts[11], str(len('FAKE APP')))
+
+ # Outer most logger should have logged the other middleware's response
+ log_parts = self._log_parts(log1)
+ self.assertEquals(log_parts[3], 'GET')
+ self.assertEquals(log_parts[4], '/')
+ self.assertEquals(log_parts[5], 'HTTP/1.0')
+ self.assertEquals(log_parts[6], '200')
+ self.assertEquals(resp_body, 'FAKE MIDDLEWARE')
+ self.assertEquals(log_parts[11], str(len(resp_body)))
+
if __name__ == '__main__':
unittest.main()