diff --git a/swift/common/middleware/slo.py b/swift/common/middleware/slo.py index b27ab60674..cdd6bf5139 100644 --- a/swift/common/middleware/slo.py +++ b/swift/common/middleware/slo.py @@ -430,7 +430,7 @@ class SloGetContext(WSGIContext): if not sub_resp.is_success: close_if_possible(sub_resp.app_iter) raise ListingIterError( - 'ERROR: while fetching %s, GET of submanifest %s ' + 'while fetching %s, GET of submanifest %s ' 'failed with status %d' % (req.path, sub_req.path, sub_resp.status_int)) @@ -439,7 +439,7 @@ class SloGetContext(WSGIContext): return json.loads(''.join(sub_resp.app_iter)) except ValueError as err: raise ListingIterError( - 'ERROR: while fetching %s, JSON-decoding of submanifest %s ' + 'while fetching %s, JSON-decoding of submanifest %s ' 'failed with %s' % (req.path, sub_req.path, err)) def _segment_length(self, seg_dict): @@ -526,7 +526,9 @@ class SloGetContext(WSGIContext): # do this check here so that we can avoid fetching this last # manifest before raising the exception if recursion_depth >= self.max_slo_recursion_depth: - raise ListingIterError("Max recursion depth exceeded") + raise ListingIterError( + "While processing manifest %r, " + "max recursion depth was exceeded" % req.path) sub_path = get_valid_utf8_str(seg_dict['name']) sub_cont, sub_obj = split_path(sub_path, 2, 2, True) diff --git a/swift/common/request_helpers.py b/swift/common/request_helpers.py index 5caa73c16c..3684dfa07f 100644 --- a/swift/common/request_helpers.py +++ b/swift/common/request_helpers.py @@ -339,7 +339,7 @@ class SegmentedIterable(object): seg_size is not None and last_byte == seg_size - 1) if time.time() - start_time > self.max_get_time: raise SegmentError( - 'ERROR: While processing manifest %s, ' + 'While processing manifest %s, ' 'max LO GET time of %ds exceeded' % (self.name, self.max_get_time)) # The "multipart-manifest=get" query param ensures that the @@ -396,7 +396,7 @@ class SegmentedIterable(object): e_type, e_value, e_traceback = sys.exc_info() if time.time() - start_time > self.max_get_time: raise SegmentError( - 'ERROR: While processing manifest %s, ' + 'While processing manifest %s, ' 'max LO GET time of %ds exceeded' % (self.name, self.max_get_time)) if pending_req: @@ -405,7 +405,7 @@ class SegmentedIterable(object): if time.time() - start_time > self.max_get_time: raise SegmentError( - 'ERROR: While processing manifest %s, ' + 'While processing manifest %s, ' 'max LO GET time of %ds exceeded' % (self.name, self.max_get_time)) if pending_req: @@ -420,7 +420,7 @@ class SegmentedIterable(object): if not is_success(seg_resp.status_int): close_if_possible(seg_resp.app_iter) raise SegmentError( - 'ERROR: While processing manifest %s, ' + 'While processing manifest %s, ' 'got %d while retrieving %s' % (self.name, seg_resp.status_int, seg_req.path)) @@ -485,10 +485,10 @@ class SegmentedIterable(object): if bytes_left: raise SegmentError( 'Not enough bytes for %s; closing connection' % self.name) - except (ListingIterError, SegmentError): - self.logger.exception(_('ERROR: An error occurred ' - 'while retrieving segments')) - raise + except (ListingIterError, SegmentError) as err: + self.logger.error(err) + if not self.validated_first_segment: + raise finally: if self.current_resp: close_if_possible(self.current_resp.app_iter) @@ -533,12 +533,13 @@ class SegmentedIterable(object): """ if self.validated_first_segment: return - self.validated_first_segment = True try: self.peeked_chunk = next(self.app_iter) except StopIteration: pass + finally: + self.validated_first_segment = True def __iter__(self): if self.peeked_chunk is not None: diff --git a/test/unit/common/middleware/test_dlo.py b/test/unit/common/middleware/test_dlo.py index b0354b4b14..e0ed2d029d 100644 --- a/test/unit/common/middleware/test_dlo.py +++ b/test/unit/common/middleware/test_dlo.py @@ -23,7 +23,7 @@ from textwrap import dedent import time import unittest -from swift.common import exceptions, swob +from swift.common import swob from swift.common.header_key_dict import HeaderKeyDict from swift.common.middleware import dlo from swift.common.utils import closing_if_possible @@ -38,7 +38,7 @@ def md5hex(s): class DloTestCase(unittest.TestCase): - def call_dlo(self, req, app=None, expect_exception=False): + def call_dlo(self, req, app=None): if app is None: app = self.dlo @@ -53,22 +53,11 @@ class DloTestCase(unittest.TestCase): body_iter = app(req.environ, start_response) body = '' - caught_exc = None - try: - # appease the close-checker - with closing_if_possible(body_iter): - for chunk in body_iter: - body += chunk - except Exception as exc: - if expect_exception: - caught_exc = exc - else: - raise - - if expect_exception: - return status[0], headers[0], body, caught_exc - else: - return status[0], headers[0], body + # appease the close-checker + with closing_if_possible(body_iter): + for chunk in body_iter: + body += chunk + return status[0], headers[0], body def setUp(self): self.app = FakeSwift() @@ -561,7 +550,7 @@ class TestDloGetManifest(DloTestCase): environ={'REQUEST_METHOD': 'GET'}, headers={'If-Modified-Since': 'Wed, 12 Feb 2014 22:24:52 GMT', 'If-Unmodified-Since': 'Thu, 13 Feb 2014 23:25:53 GMT'}) - status, headers, body, exc = self.call_dlo(req, expect_exception=True) + status, headers, body = self.call_dlo(req) for _, _, hdrs in self.app.calls_with_headers[1:]: self.assertFalse('If-Modified-Since' in hdrs) @@ -576,10 +565,10 @@ class TestDloGetManifest(DloTestCase): environ={'REQUEST_METHOD': 'GET'}) status, headers, body = self.call_dlo(req) self.assertEqual(status, "409 Conflict") - err_lines = self.dlo.logger.get_lines_for_level('error') - self.assertEqual(len(err_lines), 1) - self.assertTrue(err_lines[0].startswith( - 'ERROR: An error occurred while retrieving segments')) + self.assertEqual(self.dlo.logger.get_lines_for_level('error'), [ + 'While processing manifest /v1/AUTH_test/mancon/manifest, ' + 'got 403 while retrieving /v1/AUTH_test/c/seg_01', + ]) def test_error_fetching_second_segment(self): self.app.register( @@ -588,16 +577,15 @@ class TestDloGetManifest(DloTestCase): req = swob.Request.blank('/v1/AUTH_test/mancon/manifest', environ={'REQUEST_METHOD': 'GET'}) - status, headers, body, exc = self.call_dlo(req, expect_exception=True) + status, headers, body = self.call_dlo(req) headers = HeaderKeyDict(headers) - self.assertTrue(isinstance(exc, exceptions.SegmentError)) self.assertEqual(status, "200 OK") self.assertEqual(''.join(body), "aaaaa") # first segment made it out - err_lines = self.dlo.logger.get_lines_for_level('error') - self.assertEqual(len(err_lines), 1) - self.assertTrue(err_lines[0].startswith( - 'ERROR: An error occurred while retrieving segments')) + self.assertEqual(self.dlo.logger.get_lines_for_level('error'), [ + 'While processing manifest /v1/AUTH_test/mancon/manifest, ' + 'got 403 while retrieving /v1/AUTH_test/c/seg_02', + ]) def test_error_listing_container_first_listing_request(self): self.app.register( @@ -620,9 +608,7 @@ class TestDloGetManifest(DloTestCase): environ={'REQUEST_METHOD': 'GET'}, headers={'Range': 'bytes=-5'}) with mock.patch(LIMIT, 3): - status, headers, body, exc = self.call_dlo( - req, expect_exception=True) - self.assertTrue(isinstance(exc, exceptions.ListingIterError)) + status, headers, body = self.call_dlo(req) self.assertEqual(status, "200 OK") self.assertEqual(body, "aaaaabbbbbccccc") @@ -634,10 +620,9 @@ class TestDloGetManifest(DloTestCase): req = swob.Request.blank('/v1/AUTH_test/mancon/manifest', environ={'REQUEST_METHOD': 'GET'}) - status, headers, body, exc = self.call_dlo(req, expect_exception=True) + status, headers, body = self.call_dlo(req) headers = HeaderKeyDict(headers) - self.assertTrue(isinstance(exc, exceptions.SegmentError)) self.assertEqual(status, "200 OK") self.assertEqual(''.join(body), "aaaaabbWRONGbb") # stop after error @@ -712,12 +697,10 @@ class TestDloGetManifest(DloTestCase): mock.patch('swift.common.request_helpers.is_success', mock_is_success), \ mock.patch.object(dlo, 'is_success', mock_is_success): - status, headers, body, exc = self.call_dlo( - req, expect_exception=True) + status, headers, body = self.call_dlo(req) self.assertEqual(status, '200 OK') self.assertEqual(body, 'aaaaabbbbbccccc') - self.assertTrue(isinstance(exc, exceptions.SegmentError)) def test_get_oversize_segment(self): # If we send a Content-Length header to the client, it's based on the @@ -735,13 +718,12 @@ class TestDloGetManifest(DloTestCase): req = swob.Request.blank( '/v1/AUTH_test/mancon/manifest', environ={'REQUEST_METHOD': 'GET'}) - status, headers, body, exc = self.call_dlo(req, expect_exception=True) + status, headers, body = self.call_dlo(req) headers = HeaderKeyDict(headers) self.assertEqual(status, '200 OK') # sanity check self.assertEqual(headers.get('Content-Length'), '25') # sanity check self.assertEqual(body, 'aaaaabbbbbccccccccccccccc') - self.assertTrue(isinstance(exc, exceptions.SegmentError)) self.assertEqual( self.app.calls, [('GET', '/v1/AUTH_test/mancon/manifest'), @@ -768,13 +750,12 @@ class TestDloGetManifest(DloTestCase): req = swob.Request.blank( '/v1/AUTH_test/mancon/manifest', environ={'REQUEST_METHOD': 'GET'}) - status, headers, body, exc = self.call_dlo(req, expect_exception=True) + status, headers, body = self.call_dlo(req) headers = HeaderKeyDict(headers) self.assertEqual(status, '200 OK') # sanity check self.assertEqual(headers.get('Content-Length'), '25') # sanity check self.assertEqual(body, 'aaaaabbbbbccccdddddeeeee') - self.assertTrue(isinstance(exc, exceptions.SegmentError)) def test_get_undersize_segment_range(self): # Shrink it by a single byte @@ -787,13 +768,12 @@ class TestDloGetManifest(DloTestCase): '/v1/AUTH_test/mancon/manifest', environ={'REQUEST_METHOD': 'GET'}, headers={'Range': 'bytes=0-14'}) - status, headers, body, exc = self.call_dlo(req, expect_exception=True) + status, headers, body = self.call_dlo(req) headers = HeaderKeyDict(headers) self.assertEqual(status, '206 Partial Content') # sanity check self.assertEqual(headers.get('Content-Length'), '15') # sanity check self.assertEqual(body, 'aaaaabbbbbcccc') - self.assertTrue(isinstance(exc, exceptions.SegmentError)) def test_get_with_auth_overridden(self): auth_got_called = [0] diff --git a/test/unit/common/middleware/test_slo.py b/test/unit/common/middleware/test_slo.py index d0585276ee..3f4adc0f86 100644 --- a/test/unit/common/middleware/test_slo.py +++ b/test/unit/common/middleware/test_slo.py @@ -23,7 +23,6 @@ import unittest from mock import patch from StringIO import StringIO from swift.common import swob, utils -from swift.common.exceptions import ListingIterError, SegmentError from swift.common.header_key_dict import HeaderKeyDict from swift.common.middleware import slo from swift.common.swob import Request, HTTPException @@ -61,7 +60,7 @@ class SloTestCase(unittest.TestCase): self.slo = slo.filter_factory(slo_conf)(self.app) self.slo.logger = self.app.logger - def call_app(self, req, app=None, expect_exception=False): + def call_app(self, req, app=None): if app is None: app = self.app @@ -76,22 +75,11 @@ class SloTestCase(unittest.TestCase): body_iter = app(req.environ, start_response) body = '' - caught_exc = None - try: - # appease the close-checker - with closing_if_possible(body_iter): - for chunk in body_iter: - body += chunk - except Exception as exc: - if expect_exception: - caught_exc = exc - else: - raise - - if expect_exception: - return status[0], headers[0], body, caught_exc - else: - return status[0], headers[0], body + # appease the close-checker + with closing_if_possible(body_iter): + for chunk in body_iter: + body += chunk + return status[0], headers[0], body def call_slo(self, req, **kwargs): return self.call_app(req, app=self.slo, **kwargs) @@ -2473,15 +2461,19 @@ class TestSloGetManifest(SloTestCase): req = Request.blank( '/v1/AUTH_test/gettest/man1', environ={'REQUEST_METHOD': 'GET'}) - status, headers, body, exc = self.call_slo(req, expect_exception=True) + status, headers, body = self.call_slo(req) headers = HeaderKeyDict(headers) - self.assertIsInstance(exc, ListingIterError) # we don't know at header-sending time that things are going to go # wrong, so we end up with a 200 and a truncated body self.assertEqual(status, '200 OK') self.assertEqual(body, ('body01body02body03body04body05' + 'body06body07body08body09body10')) + # but the error shows up in logs + self.assertEqual(self.slo.logger.get_lines_for_level('error'), [ + "While processing manifest '/v1/AUTH_test/gettest/man1', " + "max recursion depth was exceeded" + ]) # make sure we didn't keep asking for segments self.assertEqual(self.app.call_count, 20) @@ -2592,10 +2584,10 @@ class TestSloGetManifest(SloTestCase): self.assertEqual(status, '409 Conflict') self.assertEqual(self.app.call_count, 10) - error_lines = self.slo.logger.get_lines_for_level('error') - self.assertEqual(len(error_lines), 1) - self.assertTrue(error_lines[0].startswith( - 'ERROR: An error occurred while retrieving segments')) + self.assertEqual(self.slo.logger.get_lines_for_level('error'), [ + "While processing manifest '/v1/AUTH_test/gettest/man1', " + "max recursion depth was exceeded" + ]) def test_get_with_if_modified_since(self): # It's important not to pass the If-[Un]Modified-Since header to the @@ -2606,7 +2598,8 @@ class TestSloGetManifest(SloTestCase): environ={'REQUEST_METHOD': 'GET'}, headers={'If-Modified-Since': 'Wed, 12 Feb 2014 22:24:52 GMT', 'If-Unmodified-Since': 'Thu, 13 Feb 2014 23:25:53 GMT'}) - status, headers, body, exc = self.call_slo(req, expect_exception=True) + status, headers, body = self.call_slo(req) + self.assertEqual(self.slo.logger.get_lines_for_level('error'), []) for _, _, hdrs in self.app.calls_with_headers[1:]: self.assertFalse('If-Modified-Since' in hdrs) @@ -2619,11 +2612,14 @@ class TestSloGetManifest(SloTestCase): req = Request.blank( '/v1/AUTH_test/gettest/manifest-abcd', environ={'REQUEST_METHOD': 'GET'}) - status, headers, body, exc = self.call_slo(req, expect_exception=True) + status, headers, body = self.call_slo(req) headers = HeaderKeyDict(headers) - self.assertIsInstance(exc, SegmentError) self.assertEqual(status, '200 OK') + self.assertEqual(self.slo.logger.get_lines_for_level('error'), [ + 'While processing manifest /v1/AUTH_test/gettest/manifest-abcd, ' + 'got 401 while retrieving /v1/AUTH_test/gettest/c_15' + ]) self.assertEqual(self.app.calls, [ ('GET', '/v1/AUTH_test/gettest/manifest-abcd'), ('GET', '/v1/AUTH_test/gettest/manifest-bc'), @@ -2638,11 +2634,15 @@ class TestSloGetManifest(SloTestCase): req = Request.blank( '/v1/AUTH_test/gettest/manifest-abcd', environ={'REQUEST_METHOD': 'GET'}) - status, headers, body, exc = self.call_slo(req, expect_exception=True) + status, headers, body = self.call_slo(req) - self.assertIsInstance(exc, ListingIterError) self.assertEqual("200 OK", status) self.assertEqual("aaaaa", body) + self.assertEqual(self.slo.logger.get_lines_for_level('error'), [ + 'while fetching /v1/AUTH_test/gettest/manifest-abcd, GET of ' + 'submanifest /v1/AUTH_test/gettest/manifest-bc failed with ' + 'status 401' + ]) self.assertEqual(self.app.calls, [ ('GET', '/v1/AUTH_test/gettest/manifest-abcd'), # This one has the error, and so is the last one we fetch. @@ -2672,10 +2672,11 @@ class TestSloGetManifest(SloTestCase): status, headers, body = self.call_slo(req) self.assertEqual('409 Conflict', status) - error_lines = self.slo.logger.get_lines_for_level('error') - self.assertEqual(len(error_lines), 1) - self.assertTrue(error_lines[0].startswith( - 'ERROR: An error occurred while retrieving segments')) + self.assertEqual(self.slo.logger.get_lines_for_level('error'), [ + 'while fetching /v1/AUTH_test/gettest/manifest-manifest-a, GET ' + 'of submanifest /v1/AUTH_test/gettest/manifest-a failed with ' + 'status 403' + ]) def test_invalid_json_submanifest(self): self.app.register( @@ -2688,11 +2689,15 @@ class TestSloGetManifest(SloTestCase): req = Request.blank( '/v1/AUTH_test/gettest/manifest-abcd', environ={'REQUEST_METHOD': 'GET'}) - status, headers, body, exc = self.call_slo(req, expect_exception=True) + status, headers, body = self.call_slo(req) - self.assertIsInstance(exc, ListingIterError) self.assertEqual('200 OK', status) self.assertEqual(body, 'aaaaa') + self.assertEqual(self.slo.logger.get_lines_for_level('error'), [ + 'while fetching /v1/AUTH_test/gettest/manifest-abcd, ' + 'JSON-decoding of submanifest /v1/AUTH_test/gettest/manifest-bc ' + 'failed with No JSON object could be decoded' + ]) def test_mismatched_etag(self): self.app.register( @@ -2709,11 +2714,14 @@ class TestSloGetManifest(SloTestCase): req = Request.blank( '/v1/AUTH_test/gettest/manifest-a-b-badetag-c', environ={'REQUEST_METHOD': 'GET'}) - status, headers, body, exc = self.call_slo(req, expect_exception=True) + status, headers, body = self.call_slo(req) - self.assertIsInstance(exc, SegmentError) self.assertEqual('200 OK', status) self.assertEqual(body, 'aaaaa') + self.assertEqual(self.slo.logger.get_lines_for_level('error'), [ + 'Object segment no longer valid: /v1/AUTH_test/gettest/b_10 ' + 'etag: 82136b4240d6ce4ea7d03e51469a393b != wrong! or 10 != 10.' + ]) def test_mismatched_size(self): self.app.register( @@ -2730,11 +2738,15 @@ class TestSloGetManifest(SloTestCase): req = Request.blank( '/v1/AUTH_test/gettest/manifest-a-b-badsize-c', environ={'REQUEST_METHOD': 'GET'}) - status, headers, body, exc = self.call_slo(req, expect_exception=True) + status, headers, body = self.call_slo(req) - self.assertIsInstance(exc, SegmentError) self.assertEqual('200 OK', status) self.assertEqual(body, 'aaaaa') + self.assertEqual(self.slo.logger.get_lines_for_level('error'), [ + 'Object segment no longer valid: /v1/AUTH_test/gettest/b_10 ' + 'etag: 82136b4240d6ce4ea7d03e51469a393b != ' + '82136b4240d6ce4ea7d03e51469a393b or 10 != 999999.' + ]) def test_first_segment_mismatched_etag(self): self.app.register('GET', '/v1/AUTH_test/gettest/manifest-badetag', @@ -2750,10 +2762,10 @@ class TestSloGetManifest(SloTestCase): status, headers, body = self.call_slo(req) self.assertEqual('409 Conflict', status) - error_lines = self.slo.logger.get_lines_for_level('error') - self.assertEqual(len(error_lines), 1) - self.assertTrue(error_lines[0].startswith( - 'ERROR: An error occurred while retrieving segments')) + self.assertEqual(self.slo.logger.get_lines_for_level('error'), [ + 'Object segment no longer valid: /v1/AUTH_test/gettest/a_5 ' + 'etag: 594f803b380a41396ed63dca39503542 != wrong! or 5 != 5.' + ]) def test_first_segment_mismatched_size(self): self.app.register('GET', '/v1/AUTH_test/gettest/manifest-badsize', @@ -2769,10 +2781,11 @@ class TestSloGetManifest(SloTestCase): status, headers, body = self.call_slo(req) self.assertEqual('409 Conflict', status) - error_lines = self.slo.logger.get_lines_for_level('error') - self.assertEqual(len(error_lines), 1) - self.assertTrue(error_lines[0].startswith( - 'ERROR: An error occurred while retrieving segments')) + self.assertEqual(self.slo.logger.get_lines_for_level('error'), [ + 'Object segment no longer valid: /v1/AUTH_test/gettest/a_5 ' + 'etag: 594f803b380a41396ed63dca39503542 != ' + '594f803b380a41396ed63dca39503542 or 5 != 999999.' + ]) @patch('swift.common.request_helpers.time') def test_download_takes_too_long(self, mock_time): @@ -2791,11 +2804,13 @@ class TestSloGetManifest(SloTestCase): '/v1/AUTH_test/gettest/manifest-abcd', environ={'REQUEST_METHOD': 'GET'}) - status, headers, body, exc = self.call_slo( - req, expect_exception=True) + status, headers, body = self.call_slo(req) - self.assertIsInstance(exc, SegmentError) self.assertEqual(status, '200 OK') + self.assertEqual(self.slo.logger.get_lines_for_level('error'), [ + 'While processing manifest /v1/AUTH_test/gettest/manifest-abcd, ' + 'max LO GET time of 86400s exceeded' + ]) self.assertEqual(self.app.calls, [ ('GET', '/v1/AUTH_test/gettest/manifest-abcd'), ('GET', '/v1/AUTH_test/gettest/manifest-bc'), @@ -2820,10 +2835,11 @@ class TestSloGetManifest(SloTestCase): status, headers, body = self.call_slo(req) self.assertEqual('409 Conflict', status) - error_lines = self.slo.logger.get_lines_for_level('error') - self.assertEqual(len(error_lines), 1) - self.assertTrue(error_lines[0].startswith( - 'ERROR: An error occurred while retrieving segments')) + self.assertEqual(self.slo.logger.get_lines_for_level('error'), [ + 'While processing manifest /v1/AUTH_test/gettest/' + 'manifest-not-exists, got 404 while retrieving /v1/AUTH_test/' + 'gettest/not_exists_obj' + ]) class TestSloConditionalGetOldManifest(SloTestCase):