openstack/swift
Code Issues Proposed changes

Merge "Stop logging tracebacks on bad xLOs"

Browse Source
This commit is contained in:
Zuul 2017-10-20 01:46:00 +00:00 committed by Gerrit Code Review
commit 1da1bfb381
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):