From 108501a8c130f4b013c75603b0263f585f6ba535 Mon Sep 17 00:00:00 2001 From: Janie Richling Date: Sat, 11 Mar 2017 13:30:35 -0600 Subject: [PATCH] Log the correct request type of a subrequest downstream of copy Before this change, subrequests made while servicing a copy would result in logging the request type from the copy PUT/GET request instead of the type from the subrequest being logged. In order to have the correct requst type logged for subrequests: - Changed subrequest environments to not inherit the orig_req_method of the enclosing request. - Changed copy to be more picky about when it sets orig_req_method In addition, subrequest environments will no longer inherit the swift.log_info from the enclosing request. That inheritance had been added at Ic96a92e938589a2f6add35a40741fd062f1c29eb along with swift.orig_req_method. Change-Id: I1ccb2665b6cd2887659e548e55a26aa00de879e3 Closes-Bug: #1657246 --- swift/common/middleware/copy.py | 10 +- swift/common/wsgi.py | 3 +- test/unit/common/middleware/test_copy.py | 24 ++- .../middleware/test_subrequest_logging.py | 178 ++++++++++++++++++ 4 files changed, 201 insertions(+), 14 deletions(-) create mode 100644 test/unit/common/middleware/test_subrequest_logging.py diff --git a/swift/common/middleware/copy.py b/swift/common/middleware/copy.py index 0c22a31f39..312d406aa0 100644 --- a/swift/common/middleware/copy.py +++ b/swift/common/middleware/copy.py @@ -321,17 +321,17 @@ class ServerSideCopyMiddleware(object): self.container_name = container self.object_name = obj - # Save off original request method (COPY/POST) in case it gets mutated - # into PUT during handling. This way logging can display the method - # the client actually sent. - req.environ['swift.orig_req_method'] = req.method - try: + # In some cases, save off original request method since it gets + # mutated into PUT during handling. This way logging can display + # the method the client actually sent. if req.method == 'PUT' and req.headers.get('X-Copy-From'): return self.handle_PUT(req, start_response) elif req.method == 'COPY': + req.environ['swift.orig_req_method'] = req.method return self.handle_COPY(req, start_response) elif req.method == 'POST' and self.object_post_as_copy: + req.environ['swift.orig_req_method'] = req.method return self.handle_object_post_as_copy(req, start_response) elif req.method == 'OPTIONS': # Does not interfere with OPTIONS response from diff --git a/swift/common/wsgi.py b/swift/common/wsgi.py index 4432f32efd..7f87bb0807 100644 --- a/swift/common/wsgi.py +++ b/swift/common/wsgi.py @@ -1111,8 +1111,7 @@ def make_env(env, method=None, path=None, agent='Swift', query_string=None, 'SERVER_PROTOCOL', 'swift.cache', 'swift.source', 'swift.trans_id', 'swift.authorize_override', 'swift.authorize', 'HTTP_X_USER_ID', 'HTTP_X_PROJECT_ID', - 'HTTP_REFERER', 'swift.orig_req_method', 'swift.log_info', - 'swift.infocache'): + 'HTTP_REFERER', 'swift.infocache'): if name in env: newenv[name] = env[name] if method: diff --git a/test/unit/common/middleware/test_copy.py b/test/unit/common/middleware/test_copy.py index 60f2ba606b..08d9acdfb1 100644 --- a/test/unit/common/middleware/test_copy.py +++ b/test/unit/common/middleware/test_copy.py @@ -150,13 +150,15 @@ class TestServerSideCopyMiddleware(unittest.TestCase): self.assertEqual(len(self.authorized), 1) self.assertRequestEqual(req, self.authorized[0]) - def test_object_delete_pass_through(self): - self.app.register('DELETE', '/v1/a/c/o', swob.HTTPOk, {}) - req = Request.blank('/v1/a/c/o', method='DELETE') - status, headers, body = self.call_ssc(req) - self.assertEqual(status, '200 OK') - self.assertEqual(len(self.authorized), 1) - self.assertRequestEqual(req, self.authorized[0]) + def test_object_pass_through_methods(self): + for method in ['DELETE', 'GET', 'HEAD', 'REPLICATE']: + self.app.register(method, '/v1/a/c/o', swob.HTTPOk, {}) + req = Request.blank('/v1/a/c/o', method=method) + status, headers, body = self.call_ssc(req) + self.assertEqual(status, '200 OK') + self.assertEqual(len(self.authorized), 1) + self.assertRequestEqual(req, self.authorized[0]) + self.assertNotIn('swift.orig_req_method', req.environ) def test_POST_as_COPY_simple(self): self.app.register('GET', '/v1/a/c/o', swob.HTTPOk, {}, 'passed') @@ -166,6 +168,8 @@ class TestServerSideCopyMiddleware(unittest.TestCase): self.assertEqual(status, '202 Accepted') self.assertEqual(len(self.authorized), 1) self.assertRequestEqual(req, self.authorized[0]) + # For basic test cases, assert orig_req_method behavior + self.assertEqual(req.environ['swift.orig_req_method'], 'POST') def test_POST_as_COPY_201_return_202(self): self.app.register('GET', '/v1/a/c/o', swob.HTTPOk, {}, 'passed') @@ -258,6 +262,8 @@ class TestServerSideCopyMiddleware(unittest.TestCase): self.assertEqual('/v1/a/c/o2', self.authorized[1].path) self.assertEqual(self.app.swift_sources[0], 'SSC') self.assertEqual(self.app.swift_sources[1], 'SSC') + # For basic test cases, assert orig_req_method behavior + self.assertNotIn('swift.orig_req_method', req.environ) def test_static_large_object_manifest(self): self.app.register('GET', '/v1/a/c/o', swob.HTTPOk, @@ -663,6 +669,8 @@ class TestServerSideCopyMiddleware(unittest.TestCase): ('PUT', '/v1/a/c/o-copy')]) self.assertIn('etag', self.app.headers[1]) self.assertEqual(self.app.headers[1]['etag'], 'is sent') + # For basic test cases, assert orig_req_method behavior + self.assertEqual(req.environ['swift.orig_req_method'], 'COPY') def test_basic_DLO(self): self.app.register('GET', '/v1/a/c/o', swob.HTTPOk, { @@ -1191,6 +1199,8 @@ class TestServerSideCopyMiddleware(unittest.TestCase): self.assertEqual(len(self.authorized), 1) self.assertEqual('OPTIONS', self.authorized[0].method) self.assertEqual('/v1/a/c/o', self.authorized[0].path) + # For basic test cases, assert orig_req_method behavior + self.assertNotIn('swift.orig_req_method', req.environ) def test_COPY_in_OPTIONS_response_CORS(self): self.app.register('OPTIONS', '/v1/a/c/o', swob.HTTPOk, diff --git a/test/unit/common/middleware/test_subrequest_logging.py b/test/unit/common/middleware/test_subrequest_logging.py new file mode 100644 index 0000000000..1754215082 --- /dev/null +++ b/test/unit/common/middleware/test_subrequest_logging.py @@ -0,0 +1,178 @@ +# Copyright (c) 2016-2017 OpenStack Foundation +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or +# implied. +# See the License for the specific language governing permissions and +# limitations under the License. +import unittest + +from swift.common.middleware import copy, proxy_logging +from swift.common.swob import Request, HTTPOk +from swift.common.utils import close_if_possible +from swift.common.wsgi import make_subrequest +from test.unit import FakeLogger +from test.unit.common.middleware.helpers import FakeSwift + + +SUB_GET_PATH = '/v1/a/c/sub_get' +SUB_PUT_POST_PATH = '/v1/a/c/sub_put' + + +class FakeFilter(object): + def __init__(self, app, conf, register): + self.body = ['FAKE MIDDLEWARE'] + self.conf = conf + self.app = app + self.register = register + self.logger = None + + def __call__(self, env, start_response): + path = SUB_PUT_POST_PATH + if env['REQUEST_METHOD'] is 'GET': + path = SUB_GET_PATH + + # Make a subrequest that will be logged + hdrs = {'content-type': 'text/plain'} + sub_req = make_subrequest(env, path=path, + method=self.conf['subrequest_type'], + headers=hdrs, + agent='FakeApp', + swift_source='FA') + self.register(self.conf['subrequest_type'], + path, HTTPOk, headers=hdrs) + + resp = sub_req.get_response(self.app) + close_if_possible(resp.app_iter) + + def _start_response(status, headers, exc_info=None): + return start_response(status, headers, exc_info) + + return self.app(env, start_response) + + +class FakeApp(object): + def __init__(self, conf): + self.fake_logger = FakeLogger() + self.fake_swift = self.app = FakeSwift() + self.register = self.fake_swift.register + for filter in reversed([ + proxy_logging.filter_factory, + copy.filter_factory, + lambda conf: lambda app: FakeFilter(app, conf, self.register), + proxy_logging.filter_factory]): + self.app = filter(conf)(self.app) + self.app.logger = self.fake_logger + if hasattr(self.app, 'access_logger'): + self.app.access_logger = self.fake_logger + + if conf['subrequest_type'] == 'GET': + self.register(conf['subrequest_type'], SUB_GET_PATH, HTTPOk, {}) + else: + self.register(conf['subrequest_type'], + SUB_PUT_POST_PATH, HTTPOk, {}) + + @property + def __call__(self): + return self.app.__call__ + + +class TestSubRequestLogging(unittest.TestCase): + path = '/v1/a/c/o' + + def _test_subrequest_logged(self, subrequest_type): + # Test that subrequests made downstream from Copy PUT will be logged + # with the request type of the subrequest as opposed to the GET/PUT. + + app = FakeApp({'subrequest_type': subrequest_type}) + + hdrs = {'content-type': 'text/plain', 'X-Copy-From': 'test/obj'} + req = Request.blank(self.path, method='PUT', headers=hdrs) + + app.register('PUT', self.path, HTTPOk, headers=hdrs) + app.register('GET', '/v1/a/test/obj', HTTPOk, headers=hdrs) + + req.get_response(app) + info_log_lines = app.fake_logger.get_lines_for_level('info') + self.assertEqual(len(info_log_lines), 5) + self.assertTrue(info_log_lines[0].startswith('Copying object')) + subreq_get = '%s %s' % (subrequest_type, SUB_GET_PATH) + subreq_put = '%s %s' % (subrequest_type, SUB_PUT_POST_PATH) + origput = 'PUT %s' % self.path + copyget = 'GET %s' % '/v1/a/test/obj' + # expect GET subreq, copy GET, PUT subreq, orig PUT + self.assertTrue(subreq_get in info_log_lines[1]) + self.assertTrue(copyget in info_log_lines[2]) + self.assertTrue(subreq_put in info_log_lines[3]) + self.assertTrue(origput in info_log_lines[4]) + + def test_subrequest_logged_x_copy_from(self): + self._test_subrequest_logged('HEAD') + self._test_subrequest_logged('GET') + self._test_subrequest_logged('POST') + self._test_subrequest_logged('PUT') + self._test_subrequest_logged('DELETE') + + def _test_subrequest_logged_POST(self, subrequest_type, + post_as_copy=False): + # Test that subrequests made downstream from Copy POST will be logged + # with the request type of the subrequest as opposed to the GET/PUT. + + app = FakeApp({'subrequest_type': subrequest_type, + 'object_post_as_copy': post_as_copy}) + + hdrs = {'content-type': 'text/plain'} + req = Request.blank(self.path, method='POST', headers=hdrs) + + app.register('POST', self.path, HTTPOk, headers=hdrs) + expect_lines = 2 + if post_as_copy: + app.register('PUT', self.path, HTTPOk, headers=hdrs) + app.register('GET', '/v1/a/c/o', HTTPOk, headers=hdrs) + expect_lines = 4 + + req.get_response(app) + info_log_lines = app.fake_logger.get_lines_for_level('info') + self.assertEqual(len(info_log_lines), expect_lines) + self.assertTrue('Copying object' not in info_log_lines[0]) + + subreq_put_post = '%s %s' % (subrequest_type, SUB_PUT_POST_PATH) + origpost = 'POST %s' % self.path + copyget = 'GET %s' % self.path + + if post_as_copy: + # post_as_copy expect GET subreq, copy GET, PUT subreq, orig POST + subreq_get = '%s %s' % (subrequest_type, SUB_GET_PATH) + self.assertTrue(subreq_get in info_log_lines[0]) + self.assertTrue(copyget in info_log_lines[1]) + self.assertTrue(subreq_put_post in info_log_lines[2]) + self.assertTrue(origpost in info_log_lines[3]) + else: + # fast post expect POST subreq, original POST + self.assertTrue(subreq_put_post in info_log_lines[0]) + self.assertTrue(origpost in info_log_lines[1]) + + def test_subrequest_logged_post_as_copy_with_POST_fast_post(self): + self._test_subrequest_logged_POST('HEAD', post_as_copy=False) + self._test_subrequest_logged_POST('GET', post_as_copy=False) + self._test_subrequest_logged_POST('POST', post_as_copy=False) + self._test_subrequest_logged_POST('PUT', post_as_copy=False) + self._test_subrequest_logged_POST('DELETE', post_as_copy=False) + + def test_subrequest_logged_post_as_copy_with_POST(self): + self._test_subrequest_logged_POST('HEAD', post_as_copy=True) + self._test_subrequest_logged_POST('GET', post_as_copy=True) + self._test_subrequest_logged_POST('POST', post_as_copy=True) + self._test_subrequest_logged_POST('PUT', post_as_copy=True) + self._test_subrequest_logged_POST('DELETE', post_as_copy=True) + + +if __name__ == '__main__': + unittest.main()