openstack/swift
Code Issues Proposed changes

Stop logging tracebacks on bad xLOs

Browse Source 
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
This commit is contained in:
Tim Burke 2017-10-17 22:49:39 +00:00
parent ae2a75ad52
commit e001c02ff9
4 changed files with 108 additions and 109 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

8
swift/common/middleware/slo.py
View File

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

19
swift/common/request_helpers.py
View File

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

66
test/unit/common/middleware/test_dlo.py
View File

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

124
test/unit/common/middleware/test_slo.py
View File

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