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()