proxy-server: log correct path when listing parsing fails

The proxy may use a sub-request to fetch a container listing response,
for example for updating shard ranges. If it then fails to parse the
response, it should use the sub-request path when logging a warning or
error. Before, the proxy would use the original request path which may
have been to an object.

Change-Id: Id904f4cc0f911f9e6e53d4b3ad7f98aacd2b335d
This commit is contained in:
Alistair Coles 2024-06-25 10:45:22 +01:00
parent d1a7bc6afd
commit 130377bd27
3 changed files with 121 additions and 32 deletions

View File

@ -2452,9 +2452,10 @@ class Controller(object):
def _parse_listing_response(self, req, response): def _parse_listing_response(self, req, response):
if not is_success(response.status_int): if not is_success(response.status_int):
record_type = req.headers.get('X-Backend-Record-Type')
self.logger.warning( self.logger.warning(
'Failed to get container listing from %s: %s', 'Failed to get container %s listing from %s: %s',
req.path_qs, response.status_int) record_type, req.path_qs, response.status_int)
return None return None
try: try:
@ -2463,9 +2464,10 @@ class Controller(object):
raise ValueError('not a list') raise ValueError('not a list')
return data return data
except ValueError as err: except ValueError as err:
record_type = response.headers.get('X-Backend-Record-Type')
self.logger.error( self.logger.error(
'Problem with listing response from %s: %r', 'Problem with container %s listing response from %s: %r',
req.path_qs, err) record_type, req.path_qs, err)
return None return None
def _get_container_listing(self, req, account, container, headers=None, def _get_container_listing(self, req, account, container, headers=None,
@ -2495,7 +2497,7 @@ class Controller(object):
self.logger.debug( self.logger.debug(
'Get listing from %s %s' % (subreq.path_qs, headers)) 'Get listing from %s %s' % (subreq.path_qs, headers))
response = self.app.handle_request(subreq) response = self.app.handle_request(subreq)
data = self._parse_listing_response(req, response) data = self._parse_listing_response(subreq, response)
return data, response return data, response
def _parse_namespaces(self, req, listing, response): def _parse_namespaces(self, req, listing, response):

View File

@ -1541,10 +1541,21 @@ class TestGetShardedContainer(BaseTestContainerController):
def test_GET_sharded_container_with_deleted_shard(self): def test_GET_sharded_container_with_deleted_shard(self):
req, resp = self._do_test_GET_sharded_container_with_deleted_shards( req, resp = self._do_test_GET_sharded_container_with_deleted_shards(
[404]) [404])
warnings = self.logger.get_lines_for_level('warning') warning_lines = self.app.logger.get_lines_for_level('warning')
self.assertEqual(['Failed to get container listing from ' start = 'Failed to get container auto listing from /v1/.shards_a/c_b?'
'%s: 404' % req.path_qs], msg, _, status_txn = warning_lines[0].partition(': ')
warnings) self.assertEqual(start, msg[:len(start)])
actual_qs = msg[len(start):]
actual_params = dict(
urllib.parse.parse_qsl(actual_qs, keep_blank_values=True))
self.assertEqual({'format': 'json',
'limit': '10000',
'marker': '',
'end_marker': 'b\x00',
'states': 'listing'},
actual_params)
self.assertEqual('404', status_txn[:3])
self.assertFalse(warning_lines[1:])
self.assertEqual(resp.status_int, 503) self.assertEqual(resp.status_int, 503)
errors = self.logger.get_lines_for_level('error') errors = self.logger.get_lines_for_level('error')
self.assertEqual( self.assertEqual(
@ -1554,9 +1565,21 @@ class TestGetShardedContainer(BaseTestContainerController):
def test_GET_sharded_container_with_mix_ok_and_deleted_shard(self): def test_GET_sharded_container_with_mix_ok_and_deleted_shard(self):
req, resp = self._do_test_GET_sharded_container_with_deleted_shards( req, resp = self._do_test_GET_sharded_container_with_deleted_shards(
[200, 200, 404]) [200, 200, 404])
warnings = self.logger.get_lines_for_level('warning') warning_lines = self.app.logger.get_lines_for_level('warning')
self.assertEqual(['Failed to get container listing from ' start = 'Failed to get container auto listing from /v1/.shards_a/c_?'
'%s: 404' % req.path_qs], warnings) msg, _, status_txn = warning_lines[0].partition(': ')
self.assertEqual(start, msg[:len(start)])
actual_qs = msg[len(start):]
actual_params = dict(
urllib.parse.parse_qsl(actual_qs, keep_blank_values=True))
self.assertEqual({'format': 'json',
'limit': '9998',
'marker': 'c',
'end_marker': '',
'states': 'listing'},
actual_params)
self.assertEqual('404', status_txn[:3])
self.assertFalse(warning_lines[1:])
self.assertEqual(resp.status_int, 503) self.assertEqual(resp.status_int, 503)
errors = self.logger.get_lines_for_level('error') errors = self.logger.get_lines_for_level('error')
self.assertEqual( self.assertEqual(
@ -1566,9 +1589,21 @@ class TestGetShardedContainer(BaseTestContainerController):
def test_GET_sharded_container_mix_ok_and_unavailable_shards(self): def test_GET_sharded_container_mix_ok_and_unavailable_shards(self):
req, resp = self._do_test_GET_sharded_container_with_deleted_shards( req, resp = self._do_test_GET_sharded_container_with_deleted_shards(
[200, 200, 503]) [200, 200, 503])
warnings = self.logger.get_lines_for_level('warning') warning_lines = self.app.logger.get_lines_for_level('warning')
self.assertEqual(['Failed to get container listing from ' start = 'Failed to get container auto listing from /v1/.shards_a/c_?'
'%s: 503' % req.path_qs], warnings[-1:]) msg, _, status_txn = warning_lines[0].partition(': ')
self.assertEqual(start, msg[:len(start)])
actual_qs = msg[len(start):]
actual_params = dict(
urllib.parse.parse_qsl(actual_qs, keep_blank_values=True))
self.assertEqual({'format': 'json',
'limit': '9998',
'marker': 'c',
'end_marker': '',
'states': 'listing'},
actual_params)
self.assertEqual('503', status_txn[:3])
self.assertFalse(warning_lines[1:])
self.assertEqual(resp.status_int, 503) self.assertEqual(resp.status_int, 503)
errors = self.logger.get_lines_for_level('error') errors = self.logger.get_lines_for_level('error')
self.assertEqual( self.assertEqual(
@ -3940,21 +3975,42 @@ class TestGetPathNamespaceCaching(BaseTestContainerControllerGetPath):
self._do_test_GET_namespaces_bad_response_body( self._do_test_GET_namespaces_bad_response_body(
{'bad': 'data', 'not': ' a list'}) {'bad': 'data', 'not': ' a list'})
error_lines = self.logger.get_lines_for_level('error') error_lines = self.logger.get_lines_for_level('error')
self.assertEqual(1, len(error_lines), error_lines) start = 'Problem with container shard listing response from /v1/a/c?'
self.assertIn('Problem with listing response', error_lines[0]) msg, _, _ = error_lines[0].partition(':')
self.assertEqual(start, msg[:len(start)])
actual_qs = msg[len(start):]
actual_params = dict(
urllib.parse.parse_qsl(actual_qs, keep_blank_values=True))
self.assertEqual({'format': 'json', 'states': 'listing'},
actual_params)
self.assertFalse(error_lines[1:])
self.logger.clear() self.logger.clear()
self._do_test_GET_namespaces_bad_response_body( self._do_test_GET_namespaces_bad_response_body(
[{'not': 'a namespace'}]) [{'not': 'a namespace'}])
error_lines = self.logger.get_lines_for_level('error') error_lines = self.logger.get_lines_for_level('error')
self.assertEqual(1, len(error_lines), error_lines) start = 'Failed to get namespaces from /v1/a/c?'
self.assertIn('Failed to get namespaces', error_lines[0]) msg, _, _ = error_lines[0].partition(':')
self.assertEqual(start, msg[:len(start)])
actual_qs = msg[len(start):]
actual_params = dict(
urllib.parse.parse_qsl(actual_qs, keep_blank_values=True))
self.assertEqual({'format': 'json', 'states': 'listing'},
actual_params)
self.assertFalse(error_lines[1:])
self.logger.clear() self.logger.clear()
self._do_test_GET_namespaces_bad_response_body('not a list') self._do_test_GET_namespaces_bad_response_body('not a list')
error_lines = self.logger.get_lines_for_level('error') error_lines = self.logger.get_lines_for_level('error')
self.assertEqual(1, len(error_lines), error_lines) start = 'Problem with container shard listing response from /v1/a/c?'
self.assertIn('Problem with listing response', error_lines[0]) msg, _, _ = error_lines[0].partition(':')
self.assertEqual(start, msg[:len(start)])
actual_qs = msg[len(start):]
actual_params = dict(
urllib.parse.parse_qsl(actual_qs, keep_blank_values=True))
self.assertEqual({'format': 'json', 'states': 'listing'},
actual_params)
self.assertFalse(error_lines[1:])
def _do_test_GET_namespaces_cache_unused(self, sharding_state, req_params, def _do_test_GET_namespaces_cache_unused(self, sharding_state, req_params,
req_hdrs=None): req_hdrs=None):

View File

@ -32,7 +32,7 @@ from eventlet.queue import Empty
import six import six
from six import StringIO from six import StringIO
from six.moves import range from six.moves import range
from six.moves.urllib.parse import quote from six.moves.urllib.parse import quote, parse_qsl
if six.PY2: if six.PY2:
from email.parser import FeedParser as EmailFeedParser from email.parser import FeedParser as EmailFeedParser
else: else:
@ -7816,9 +7816,16 @@ class TestGetUpdateShard(BaseObjectControllerMixin, unittest.TestCase):
captured_hdrs.get('X-Backend-Record-Shard-Format')) captured_hdrs.get('X-Backend-Record-Shard-Format'))
self.assertIsNone(self.memcache.get('shard-updating-v2/a/c')) self.assertIsNone(self.memcache.get('shard-updating-v2/a/c'))
self.assertIsNone(actual) self.assertIsNone(actual)
lines = self.app.logger.get_lines_for_level('error')
self.assertEqual(1, len(lines)) error_lines = self.logger.get_lines_for_level('error')
self.assertIn('Problem with listing response from /v1/a/c/o', lines[0]) start = 'Problem with container shard listing response from /v1/a/c?'
msg, _, _ = error_lines[0].partition(':')
self.assertEqual(start, msg[:len(start)])
actual_qs = msg[len(start):]
actual_params = dict(parse_qsl(actual_qs, keep_blank_values=True))
self.assertEqual({'format': 'json', 'states': 'updating'},
actual_params)
self.assertFalse(error_lines[1:])
class TestGetUpdateShardUTF8(TestGetUpdateShard): class TestGetUpdateShardUTF8(TestGetUpdateShard):
@ -7864,18 +7871,34 @@ class TestGetUpdatingNamespacesErrors(BaseObjectControllerMixin,
def test_get_namespaces_empty_body(self): def test_get_namespaces_empty_body(self):
error_lines = self._check_get_namespaces_bad_data(b'') error_lines = self._check_get_namespaces_bad_data(b'')
self.assertIn('Problem with listing response', error_lines[0]) start = 'Problem with container shard listing response from /v1/a/c?'
msg, _, err = error_lines[0].partition(':')
self.assertEqual(start, msg[:len(start)])
actual_qs = msg[len(start):]
actual_params = dict(parse_qsl(actual_qs, keep_blank_values=True))
self.assertEqual({'format': 'json',
'includes': '1_test',
'states': 'updating'},
actual_params)
if six.PY2: if six.PY2:
self.assertIn('No JSON', error_lines[0]) self.assertIn('No JSON', err)
else: else:
self.assertIn('JSONDecodeError', error_lines[0]) self.assertIn('JSONDecodeError', err)
self.assertFalse(error_lines[1:]) self.assertFalse(error_lines[1:])
def test_get_namespaces_not_a_list(self): def test_get_namespaces_not_a_list(self):
body = json.dumps({}).encode('ascii') body = json.dumps({}).encode('ascii')
error_lines = self._check_get_namespaces_bad_data(body) error_lines = self._check_get_namespaces_bad_data(body)
self.assertIn('Problem with listing response', error_lines[0]) start = 'Problem with container shard listing response from /v1/a/c?'
self.assertIn('not a list', error_lines[0]) msg, _, err = error_lines[0].partition(':')
self.assertEqual(start, msg[:len(start)])
actual_qs = msg[len(start):]
actual_params = dict(parse_qsl(actual_qs, keep_blank_values=True))
self.assertEqual({'format': 'json',
'includes': '1_test',
'states': 'updating'},
actual_params)
self.assertIn('ValueError', err)
self.assertFalse(error_lines[1:]) self.assertFalse(error_lines[1:])
def test_get_namespaces_key_missing(self): def test_get_namespaces_key_missing(self):
@ -7937,8 +7960,16 @@ class TestGetUpdatingNamespacesErrors(BaseObjectControllerMixin,
self.assertIsNone(actual) self.assertIsNone(actual)
self.assertFalse(self.app.logger.get_lines_for_level('error')) self.assertFalse(self.app.logger.get_lines_for_level('error'))
warning_lines = self.app.logger.get_lines_for_level('warning') warning_lines = self.app.logger.get_lines_for_level('warning')
self.assertIn('Failed to get container listing', warning_lines[0]) start = 'Failed to get container shard listing from /v1/a/c?'
self.assertIn('/a/c', warning_lines[0]) msg, _, status_txn = warning_lines[0].partition(': ')
self.assertEqual(start, msg[:len(start)])
actual_qs = msg[len(start):]
actual_params = dict(parse_qsl(actual_qs, keep_blank_values=True))
self.assertEqual({'format': 'json',
'includes': '1_test',
'states': 'updating'},
actual_params)
self.assertEqual('404', status_txn[:3])
self.assertFalse(warning_lines[1:]) self.assertFalse(warning_lines[1:])