s3api: Use swift.backend_path to proxy-log s3api requests

... and to determine {account}, {container}, and {object} template
values, as well as statsd metric names.

UpgradeImpact:
--------------
Be aware that this will cause an increase in the proxy-logging statsd
metrics emited for s3api responses.  However, this will more accurately
reflect the state of the system.

Change-Id: Idbea6fadefb2061f83eed735ef198b88ba7aaf69

swift/common/middleware/proxy_logging.py

@@ -225,8 +225,9 @@ class ProxyLoggingMiddleware(object):
         policy_index = get_policy_index(req.headers, resp_headers)
 
         acc, cont, obj = None, None, None
-        if req.path.startswith('/v1/'):
-            _, acc, cont, obj = split_path(req.path, 1, 4, True)
+        swift_path = req.environ.get('swift.backend_path', req.path)
+        if swift_path.startswith('/v1/'):
+            _, acc, cont, obj = split_path(swift_path, 1, 4, True)
 
         replacements = {
             # Time information
@@ -300,10 +301,11 @@ class ProxyLoggingMiddleware(object):
                                             bytes_received + bytes_sent)
 
     def get_metric_name_type(self, req):
-        if req.path.startswith('/v1/'):
+        swift_path = req.environ.get('swift.backend_path', req.path)
+        if swift_path.startswith('/v1/'):
             try:
                 stat_type = [None, 'account', 'container',
-                             'object'][req.path.strip('/').count('/')]
+                             'object'][swift_path.strip('/').count('/')]
             except IndexError:
                 stat_type = 'object'
         else:

swift/common/middleware/s3api/s3api.py

@@ -306,6 +306,8 @@ class S3ApiMiddleware(object):
             resp.headers['x-amz-id-2'] = env['swift.trans_id']
             resp.headers['x-amz-request-id'] = env['swift.trans_id']
 
+        if 's3api.backend_path' in env and 'swift.backend_path' not in env:
+            env['swift.backend_path'] = env['s3api.backend_path']
         return resp(env, start_response)
 
     def handle_request(self, req):

swift/common/middleware/s3api/s3request.py

@@ -1336,10 +1336,8 @@ class S3Request(swob.Request):
                                             2, 3, True)
             # Propagate swift.backend_path in environ for middleware
             # in pipeline that need Swift PATH_INFO like ceilometermiddleware.
-            # Store PATH_INFO only the first time to ignore multipart requests.
-            if 'swift.backend_path' not in self.environ:
-                self.environ['swift.backend_path'] = \
-                    sw_resp.environ['PATH_INFO']
+            self.environ['s3api.backend_path'] = \
+                sw_resp.environ['PATH_INFO']
 
         resp = S3Response.from_swift_resp(sw_resp)
         status = resp.status_int  # pylint: disable-msg=E1101

test/unit/common/middleware/s3api/test_s3api.py

@@ -501,7 +501,7 @@ class TestS3ApiMiddleware(S3ApiTestCase):
             status, headers, body = self.call_s3api(req)
             self.assertIn('swift.backend_path', req.environ)
             self.assertEqual(
-                '/v1/AUTH_test/bucket+segments/object/123456789abcdef',
+                '/v1/AUTH_test/bucket+segments/object/123456789abcdef/1',
                 req.environ['swift.backend_path'])
 
         _, _, headers = self.swift.calls_with_headers[-1]
@@ -532,7 +532,7 @@ class TestS3ApiMiddleware(S3ApiTestCase):
             status, headers, body = self.call_s3api(req)
             self.assertIn('swift.backend_path', req.environ)
             self.assertEqual(
-                '/v1/AUTH_test/bucket+segments/object/123456789abcdef',
+                '/v1/AUTH_test/bucket+segments/object/123456789abcdef/1',
                 req.environ['swift.backend_path'])
 
         _, _, headers = self.swift.calls_with_headers[-1]

test/unit/common/middleware/test_proxy_logging.py

@@ -401,9 +401,8 @@ class TestProxyLogging(unittest.TestCase):
                         mock.MagicMock(
                             side_effect=[10000000.0, 10000000.5, 10000001.0])):
             resp = app(req.environ, start_response)
+            # exhaust generator
             resp_body = b''.join(resp)
-        # exhaust generator
-        [x for x in resp]
         log_parts = self._log_parts(app)
         self.assertEqual(log_parts[0], 'template')
         self.assertEqual(log_parts[7], 'HTTP/1.0')
@@ -417,6 +416,38 @@ class TestProxyLogging(unittest.TestCase):
         self.assertEqual(log_parts[15], '0.5')
         self.assertEqual(resp_body, b'FAKE APP')
 
+    def test_log_msg_template_s3api(self):
+        # Access logs configuration should override the default one
+        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {
+            'log_msg_template': (
+                '{protocol} {path} {method} '
+                '{account} {container} {object}')})
+        app.access_logger = FakeLogger()
+        req = Request.blank('/bucket/path/to/key', environ={
+            'REQUEST_METHOD': 'GET',
+            # This would actually get set in the app, but w/e
+            'swift.backend_path': '/v1/AUTH_test/bucket/path/to/key'})
+        with mock.patch("time.time", side_effect=[
+                18.0, 18.5, 20.71828182846]):
+            resp = app(req.environ, start_response)
+            # exhaust generator
+            resp_body = b''.join(resp)
+        log_parts = self._log_parts(app)
+        self.assertEqual(log_parts, [
+            'HTTP/1.0',
+            '/bucket/path/to/key',
+            'GET',
+            'AUTH_test',
+            'bucket',
+            'path/to/key',
+        ])
+        self.assertEqual(resp_body, b'FAKE APP')
+        self.assertTiming('object.policy.0.GET.200.timing',
+                          app, exp_timing=2.71828182846 * 1000)
+        self.assertUpdateStats([('object.GET.200.xfer', 8),
+                                ('object.policy.0.GET.200.xfer', 8)],
+                               app)
+
     def test_invalid_log_config(self):
         with self.assertRaises(ValueError):
             proxy_logging.ProxyLoggingMiddleware(FakeApp(), {