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

@@ -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
 

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

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

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':

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

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)

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 = """

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",

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