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
This commit is contained in:
Peter Portante
John Dickinson
parent
cdbf4f1f91
commit
31b9945603
@ -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:
|
||||
|
||||
@ -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()
|
||||
|
||||
Loading…
x
Reference in New Issue
Block a user