diff --git a/doc/source/development_middleware.rst b/doc/source/development_middleware.rst index 2e14e705cf..e885e87e7e 100644 --- a/doc/source/development_middleware.rst +++ b/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 -------------- diff --git a/swift/common/middleware/proxy_logging.py b/swift/common/middleware/proxy_logging.py index aad949cdd9..6bdaa9ca39 100644 --- a/swift/common/middleware/proxy_logging.py +++ b/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()) diff --git a/test/unit/common/middleware/test_proxy_logging.py b/test/unit/common/middleware/test_proxy_logging.py index 07444c09ee..d1a8285535 100644 --- a/test/unit/common/middleware/test_proxy_logging.py +++ b/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(), {})