From e001c02ff938d9aea560970fa70f3d8884a8ea33 Mon Sep 17 00:00:00 2001 From: Tim Burke Date: Tue, 17 Oct 2017 22:49:39 +0000 Subject: [PATCH] Stop logging tracebacks on bad xLOs The error messages alone should provide plenty enough information. Plus, running functional tests really shouldn't cause tracebacks. Also, tighten up tests for log messages. Change-Id: I55136484d342af756fa153d971dcb9159a435f13 --- swift/common/middleware/slo.py | 8 +- swift/common/request_helpers.py | 19 ++-- test/unit/common/middleware/test_dlo.py | 66 +++++-------- test/unit/common/middleware/test_slo.py | 124 +++++++++++++----------- 4 files changed, 108 insertions(+), 109 deletions(-) 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):