From c51e81f640274db31bf45b5253d8e99d19a7e3d6 Mon Sep 17 00:00:00 2001 From: Tim Burke Date: Wed, 31 May 2023 11:49:44 -0700 Subject: [PATCH] proxy: Bring back logging/metrics for get_*_info requests A while back, we changed get_account_info and get_container_info to call the proxy-server app directly, rather than whatever was right of the current middleware. This reduced backend request amplification on cache misses. However, it *also* meant that we stopped emitting logs or metrics in the proxy for these backend requests. This was an unfortunate and unintended break from earlier behavior. Now, extend the middleware decorating we're doing in loadapp() to include a "logged app", i.e., the app wrapped by it's right-most proxy-logging middleware. If there is not logging middleware (such as would happen for the backend servers), the "logged app" will be the main app. Make account and container info requests through *that* app, so we get logging and metrics again. Closes-Bug: #2027726 Related-Change: I49447c62abf9375541f396f984c91e128b8a05d5 Change-Id: I3f531f904340e4c8407185ed64b41d7d614a308a --- swift/common/middleware/__init__.py | 4 ++ swift/common/middleware/s3api/s3api.py | 10 ++- .../middleware/versioned_writes/__init__.py | 3 - .../versioned_writes/object_versioning.py | 7 ++ swift/common/wsgi.py | 22 ++++-- swift/proxy/controllers/base.py | 17 +++-- test/unit/common/test_wsgi.py | 67 +++++++++++++++++++ test/unit/proxy/controllers/test_base.py | 63 +++++++++++++++++ test/unit/proxy/test_server.py | 4 +- 9 files changed, 178 insertions(+), 19 deletions(-) diff --git a/swift/common/middleware/__init__.py b/swift/common/middleware/__init__.py index 00c60fda13..c465a5caf3 100644 --- a/swift/common/middleware/__init__.py +++ b/swift/common/middleware/__init__.py @@ -17,6 +17,10 @@ import re from swift.common.wsgi import WSGIContext +def app_property(name): + return property(lambda self: getattr(self.app, name)) + + class RewriteContext(WSGIContext): base_re = None diff --git a/swift/common/middleware/s3api/s3api.py b/swift/common/middleware/s3api/s3api.py index 5b1185e304..04b402787e 100644 --- a/swift/common/middleware/s3api/s3api.py +++ b/swift/common/middleware/s3api/s3api.py @@ -151,6 +151,7 @@ from swift.common.middleware.listing_formats import \ MAX_CONTAINER_LISTING_CONTENT_LENGTH from swift.common.wsgi import PipelineWrapper, loadcontext, WSGIContext +from swift.common.middleware import app_property from swift.common.middleware.s3api.exception import NotS3Request, \ InvalidSubresource from swift.common.middleware.s3api.s3request import get_request_class @@ -167,9 +168,12 @@ from swift.common.registry import register_swift_info, \ class ListingEtagMiddleware(object): def __init__(self, app): self.app = app - # Pass this along so get_container_info will have the configured - # odds to skip cache - self._pipeline_final_app = app._pipeline_final_app + + # Pass these along so get_container_info will have the configured + # odds to skip cache + _pipeline_final_app = app_property('_pipeline_final_app') + _pipeline_request_logging_app = app_property( + '_pipeline_request_logging_app') def __call__(self, env, start_response): # a lot of this is cribbed from listing_formats / swob.Request diff --git a/swift/common/middleware/versioned_writes/__init__.py b/swift/common/middleware/versioned_writes/__init__.py index 6b4b72ffe1..368cb9b716 100644 --- a/swift/common/middleware/versioned_writes/__init__.py +++ b/swift/common/middleware/versioned_writes/__init__.py @@ -47,8 +47,5 @@ def filter_factory(global_conf, **local_conf): if 'symlink' not in get_swift_info(): raise ValueError('object versioning requires symlinks') app = ObjectVersioningMiddleware(app, conf) - # Pass this along so get_container_info will have the configured - # odds to skip cache - app._pipeline_final_app = app.app._pipeline_final_app return VersionedWritesMiddleware(app, conf) return versioning_filter diff --git a/swift/common/middleware/versioned_writes/object_versioning.py b/swift/common/middleware/versioned_writes/object_versioning.py index 34d716964c..fea8abaade 100644 --- a/swift/common/middleware/versioned_writes/object_versioning.py +++ b/swift/common/middleware/versioned_writes/object_versioning.py @@ -158,6 +158,7 @@ from swift.common.http import is_success, is_client_error, HTTP_NOT_FOUND, \ from swift.common.request_helpers import get_sys_meta_prefix, \ copy_header_subset, get_reserved_name, split_reserved_name, \ constrain_req_limit +from swift.common.middleware import app_property from swift.common.middleware.symlink import TGT_OBJ_SYMLINK_HDR, \ TGT_ETAG_SYSMETA_SYMLINK_HDR, SYMLOOP_EXTEND, ALLOW_RESERVED_NAMES, \ TGT_BYTES_SYSMETA_SYMLINK_HDR, TGT_ACCT_SYMLINK_HDR @@ -1389,6 +1390,12 @@ class ObjectVersioningMiddleware(object): self.conf = conf self.logger = get_logger(conf, log_route='object_versioning') + # Pass these along so get_container_info will have the configured + # odds to skip cache + _pipeline_final_app = app_property('_pipeline_final_app') + _pipeline_request_logging_app = app_property( + '_pipeline_request_logging_app') + def account_request(self, req, api_version, account, start_response): account_ctx = AccountContext(self.app, self.logger) if req.method == 'GET': diff --git a/swift/common/wsgi.py b/swift/common/wsgi.py index c3d15c8695..93a4dad3d7 100644 --- a/swift/common/wsgi.py +++ b/swift/common/wsgi.py @@ -361,15 +361,29 @@ def loadapp(conf_file, global_conf=None, allow_modify_pipeline=True): func(PipelineWrapper(ctx)) filters = [c.create() for c in reversed(ctx.filter_contexts)] pipeline = [ultimate_app] - ultimate_app._pipeline = pipeline - ultimate_app._pipeline_final_app = ultimate_app - app = ultimate_app + request_logging_app = app = ultimate_app for filter_app in filters: app = filter_app(pipeline[0]) pipeline.insert(0, app) + if request_logging_app is ultimate_app and \ + app.__class__.__name__ == 'ProxyLoggingMiddleware': + request_logging_app = filter_app(ultimate_app) + # Set some separate-pipeline attrs + request_logging_app._pipeline = [ + request_logging_app, ultimate_app] + request_logging_app._pipeline_request_logging_app = \ + request_logging_app + request_logging_app._pipeline_final_app = ultimate_app + + for app in pipeline: app._pipeline = pipeline + # For things like making (logged) backend requests for + # get_account_info and get_container_info + app._pipeline_request_logging_app = request_logging_app + # For getting proxy-server options like *_existence_skip_cache_pct app._pipeline_final_app = ultimate_app - return app + + return pipeline[0] return ctx.create() diff --git a/swift/proxy/controllers/base.py b/swift/proxy/controllers/base.py index 6936747b3a..1f6e85d2e8 100644 --- a/swift/proxy/controllers/base.py +++ b/swift/proxy/controllers/base.py @@ -438,12 +438,14 @@ def get_container_info(env, app, swift_source=None): container = wsgi_to_str(wsgi_container) # Try to cut through all the layers to the proxy app + # (while also preserving logging) try: - app = app._pipeline_final_app + logged_app = app._pipeline_request_logging_app + proxy_app = app._pipeline_final_app except AttributeError: - pass + logged_app = proxy_app = app # Check in environment cache and in memcache (in that order) - info = _get_info_from_caches(app, env, account, container) + info = _get_info_from_caches(proxy_app, env, account, container) if not info: # Cache miss; go HEAD the container and populate the caches @@ -455,10 +457,10 @@ def get_container_info(env, app, swift_source=None): # account is successful whether the account actually has .db files # on disk or not. is_autocreate_account = account.startswith( - getattr(app, 'auto_create_account_prefix', + getattr(proxy_app, 'auto_create_account_prefix', constraints.AUTO_CREATE_ACCOUNT_PREFIX)) if not is_autocreate_account: - account_info = get_account_info(env, app, swift_source) + account_info = get_account_info(env, logged_app, swift_source) if not account_info or not is_success(account_info['status']): return headers_to_container_info({}, 0) @@ -468,7 +470,7 @@ def get_container_info(env, app, swift_source=None): # *Always* allow reserved names for get-info requests -- it's on the # caller to keep the result private-ish req.headers['X-Backend-Allow-Reserved-Names'] = 'true' - resp = req.get_response(app) + resp = req.get_response(logged_app) drain_and_close(resp) # Check in infocache to see if the proxy (or anyone else) already # populated the cache for us. If they did, just use what's there. @@ -531,8 +533,9 @@ def get_account_info(env, app, swift_source=None): account = wsgi_to_str(wsgi_account) # Try to cut through all the layers to the proxy app + # (while also preserving logging) try: - app = app._pipeline_final_app + app = app._pipeline_request_logging_app except AttributeError: pass # Check in environment cache and in memcache (in that order) diff --git a/test/unit/common/test_wsgi.py b/test/unit/common/test_wsgi.py index 1b36edf0ae..b72b78766c 100644 --- a/test/unit/common/test_wsgi.py +++ b/test/unit/common/test_wsgi.py @@ -1820,7 +1820,9 @@ class TestPipelineModification(unittest.TestCase): self.assertTrue(isinstance(app.app.app, exp), app.app.app) # Everybody gets a reference to the final app, too self.assertIs(app.app.app, app._pipeline_final_app) + self.assertIs(app.app.app, app._pipeline_request_logging_app) self.assertIs(app.app.app, app.app._pipeline_final_app) + self.assertIs(app.app.app, app.app._pipeline_request_logging_app) self.assertIs(app.app.app, app.app.app._pipeline_final_app) exp_pipeline = [app, app.app, app.app.app] self.assertEqual(exp_pipeline, app._pipeline) @@ -1845,6 +1847,71 @@ class TestPipelineModification(unittest.TestCase): exp = swift.proxy.server.Application self.assertTrue(isinstance(app.app, exp), app.app) + def test_load_app_request_logging_app(self): + config = """ + [DEFAULT] + swift_dir = TEMPDIR + + [pipeline:main] + pipeline = catch_errors proxy_logging proxy-server + + [app:proxy-server] + use = egg:swift#proxy + conn_timeout = 0.2 + + [filter:catch_errors] + use = egg:swift#catch_errors + + [filter:proxy_logging] + use = egg:swift#proxy_logging + """ + + contents = dedent(config) + with temptree(['proxy-server.conf']) as t: + conf_file = os.path.join(t, 'proxy-server.conf') + with open(conf_file, 'w') as f: + f.write(contents.replace('TEMPDIR', t)) + _fake_rings(t) + app = wsgi.loadapp(conf_file, global_conf={}) + + self.assertEqual(self.pipeline_modules(app), + ['swift.common.middleware.catch_errors', + 'swift.common.middleware.gatekeeper', + 'swift.common.middleware.proxy_logging', + 'swift.common.middleware.listing_formats', + 'swift.common.middleware.copy', + 'swift.common.middleware.dlo', + 'swift.common.middleware.versioned_writes', + 'swift.proxy.server']) + + pipeline = app._pipeline + logging_app = app._pipeline_request_logging_app + final_app = app._pipeline_final_app + # Sanity check -- loadapp returns the start of the pipeline + self.assertIs(app, pipeline[0]) + # ... and the final_app is the end + self.assertIs(final_app, pipeline[-1]) + + # The logging app is its own special short pipeline + self.assertEqual(self.pipeline_modules(logging_app), [ + 'swift.common.middleware.proxy_logging', + 'swift.proxy.server']) + self.assertNotIn(logging_app, pipeline) + self.assertIs(logging_app.app, final_app) + + # All the apps in the main pipeline got decorated identically + for app in pipeline: + self.assertIs(app._pipeline, pipeline) + self.assertIs(app._pipeline_request_logging_app, logging_app) + self.assertIs(app._pipeline_final_app, final_app) + + # Special logging app got them, too + self.assertIs(logging_app._pipeline_request_logging_app, + logging_app) + self.assertIs(logging_app._pipeline_final_app, final_app) + # Though the pipeline's different -- may or may not matter? + self.assertEqual(logging_app._pipeline, [logging_app, final_app]) + def test_proxy_unmodified_wsgi_pipeline(self): # Make sure things are sane even when we modify nothing config = """ diff --git a/test/unit/proxy/controllers/test_base.py b/test/unit/proxy/controllers/test_base.py index 723cbdad16..7366c80be8 100644 --- a/test/unit/proxy/controllers/test_base.py +++ b/test/unit/proxy/controllers/test_base.py @@ -368,7 +368,10 @@ class TestFuncs(BaseTest): # ...then decide to no-op based on the result return app(env, start_response) + # Note that we have to do some book-keeping in tests to mimic what + # would be done in swift.common.wsgi.load_app wsgi_filter._pipeline_final_app = final_app + wsgi_filter._pipeline_request_logging_app = final_app return wsgi_filter # build up a pipeline @@ -378,6 +381,66 @@ class TestFuncs(BaseTest): self.assertEqual([e['PATH_INFO'] for e in final_app.captured_envs], ['/v1/a', '/v1/a/c', '/v1/a/c/o']) + def test_get_account_info_uses_logging_app(self): + def factory(app, func=None): + calls = [] + + def wsgi_filter(env, start_response): + calls.append(env) + if func: + func(env, app) + return app(env, start_response) + + return wsgi_filter, calls + + # build up a pipeline, pretend there is a proxy_logging middleware + final_app = FakeApp() + logging_app, logging_app_calls = factory(final_app) + filtered_app, filtered_app_calls = factory(logging_app, + func=get_account_info) + # mimic what would be done in swift.common.wsgi.load_app + for app in (filtered_app, logging_app): + app._pipeline_final_app = final_app + app._pipeline_request_logging_app = logging_app + req = Request.blank("/v1/a/c/o", environ={'swift.cache': FakeCache()}) + req.get_response(filtered_app) + self.assertEqual([e['PATH_INFO'] for e in final_app.captured_envs], + ['/v1/a', '/v1/a/c/o']) + self.assertEqual([e['PATH_INFO'] for e in logging_app_calls], + ['/v1/a', '/v1/a/c/o']) + self.assertEqual([e['PATH_INFO'] for e in filtered_app_calls], + ['/v1/a/c/o']) + + def test_get_container_info_uses_logging_app(self): + def factory(app, func=None): + calls = [] + + def wsgi_filter(env, start_response): + calls.append(env) + if func: + func(env, app) + return app(env, start_response) + + return wsgi_filter, calls + + # build up a pipeline, pretend there is a proxy_logging middleware + final_app = FakeApp() + logging_app, logging_app_calls = factory(final_app) + filtered_app, filtered_app_calls = factory(logging_app, + func=get_container_info) + # mimic what would be done in swift.common.wsgi.load_app + for app in (filtered_app, logging_app): + app._pipeline_final_app = final_app + app._pipeline_request_logging_app = logging_app + req = Request.blank("/v1/a/c/o", environ={'swift.cache': FakeCache()}) + req.get_response(filtered_app) + self.assertEqual([e['PATH_INFO'] for e in final_app.captured_envs], + ['/v1/a', '/v1/a/c', '/v1/a/c/o']) + self.assertEqual([e['PATH_INFO'] for e in logging_app_calls], + ['/v1/a', '/v1/a/c', '/v1/a/c/o']) + self.assertEqual([e['PATH_INFO'] for e in filtered_app_calls], + ['/v1/a/c/o']) + def test_get_object_info_swift_source(self): app = FakeApp() req = Request.blank("/v1/a/c/o", diff --git a/test/unit/proxy/test_server.py b/test/unit/proxy/test_server.py index 668eee1ef1..7ad26b253d 100644 --- a/test/unit/proxy/test_server.py +++ b/test/unit/proxy/test_server.py @@ -515,7 +515,7 @@ class TestController(unittest.TestCase): def test_get_account_info_returns_values_as_strings(self): app = mock.MagicMock() - app._pipeline_final_app = app + app._pipeline_request_logging_app = app._pipeline_final_app = app app.account_existence_skip_cache = 0.0 memcache = mock.MagicMock() memcache.get = mock.MagicMock() @@ -542,7 +542,7 @@ class TestController(unittest.TestCase): def test_get_container_info_returns_values_as_strings(self): app = mock.MagicMock() - app._pipeline_final_app = app + app._pipeline_request_logging_app = app._pipeline_final_app = app app.container_existence_skip_cache = 0.0 memcache = mock.MagicMock() memcache.get = mock.MagicMock()