From 11bbc09bd74959206fc2b15e5a7a1811e11f37c6 Mon Sep 17 00:00:00 2001 From: gholt Date: Tue, 27 May 2014 21:10:47 +0000 Subject: [PATCH] Add debug logging to container sync requests Also fixed a bug where SimpleClient would send ?format=json for object requests, which is not necessary. Change-Id: If06a7dcebc9de2d7c8b28a046d60b902dae821c1 --- swift/common/internal_client.py | 38 ++++++++++++++++++---- swift/container/sync.py | 5 +-- test/unit/common/test_internal_client.py | 24 ++++++++++++-- test/unit/container/test_sync.py | 41 ++++++++++++------------ 4 files changed, 76 insertions(+), 32 deletions(-) diff --git a/swift/common/internal_client.py b/swift/common/internal_client.py index b7daab8838..e4c69778bb 100644 --- a/swift/common/internal_client.py +++ b/swift/common/internal_client.py @@ -20,6 +20,7 @@ import struct from sys import exc_info import zlib from swift import gettext_ as _ +from time import gmtime, strftime, time import urlparse from zlib import compressobj @@ -712,8 +713,9 @@ class SimpleClient(object): def base_request(self, method, container=None, name=None, prefix=None, headers=None, proxy=None, contents=None, - full_listing=None): + full_listing=None, logger=None, additional_info=None): # Common request method + trans_start = time() url = self.url if headers is None: @@ -727,11 +729,10 @@ class SimpleClient(object): if name: url = '%s/%s' % (url.rstrip('/'), quote(name)) - - url += '?format=json' - - if prefix: - url += '&prefix=%s' % prefix + else: + url += '?format=json' + if prefix: + url += '&prefix=%s' % prefix if proxy: proxy = urlparse.urlparse(proxy) @@ -748,6 +749,31 @@ class SimpleClient(object): body_data = json.loads(body) except ValueError: body_data = None + trans_stop = time() + if logger: + sent_content_length = 0 + for n, v in headers.items(): + nl = n.lower() + if nl == 'content-length': + try: + sent_content_length = int(v) + break + except ValueError: + pass + logger.debug("-> " + " ".join( + quote(str(x) if x else "-", ":/") + for x in ( + strftime('%Y-%m-%dT%H:%M:%S', gmtime(trans_stop)), + method, + url, + conn.getcode(), + sent_content_length, + conn.info()['content-length'], + trans_start, + trans_stop, + trans_stop - trans_start, + additional_info + ))) return [None, body_data] def retry_request(self, method, **kwargs): diff --git a/swift/container/sync.py b/swift/container/sync.py index bdde696722..8515b2bceb 100644 --- a/swift/container/sync.py +++ b/swift/container/sync.py @@ -351,7 +351,8 @@ class ContainerSync(Daemon): else: headers['x-container-sync-key'] = user_key delete_object(sync_to, name=row['name'], headers=headers, - proxy=self.select_http_proxy()) + proxy=self.select_http_proxy(), + logger=self.logger) except ClientException as err: if err.http_status != HTTP_NOT_FOUND: raise @@ -416,7 +417,7 @@ class ContainerSync(Daemon): headers['x-container-sync-key'] = user_key put_object(sync_to, name=row['name'], headers=headers, contents=FileLikeIter(body), - proxy=self.select_http_proxy()) + proxy=self.select_http_proxy(), logger=self.logger) self.container_puts += 1 self.logger.increment('puts') self.logger.timing_since('puts.timing', start_time) diff --git a/test/unit/common/test_internal_client.py b/test/unit/common/test_internal_client.py index b8628074d1..bcc60c4d11 100644 --- a/test/unit/common/test_internal_client.py +++ b/test/unit/common/test_internal_client.py @@ -20,6 +20,7 @@ import unittest from urllib import quote import zlib +from test.unit import FakeLogger from eventlet.green import urllib2 from swift.common import internal_client @@ -973,21 +974,38 @@ class TestGetAuth(unittest.TestCase): 'http://127.0.0.1', 'user', 'key', auth_version=2.0) +mock_time_value = 1401224049.98 + + +def mock_time(): + global mock_time_value + mock_time_value += 1 + return mock_time_value + + class TestSimpleClient(unittest.TestCase): @mock.patch('eventlet.green.urllib2.urlopen') @mock.patch('eventlet.green.urllib2.Request') + @mock.patch('swift.common.internal_client.time', mock_time) def test_get(self, request, urlopen): # basic GET request, only url as kwarg request.return_value.get_type.return_value = "http" urlopen.return_value.read.return_value = '' + urlopen.return_value.getcode.return_value = 200 + urlopen.return_value.info.return_value = {'content-length': '345'} sc = internal_client.SimpleClient(url='http://127.0.0.1') - retval = sc.retry_request('GET') + logger = FakeLogger() + retval = sc.retry_request( + 'GET', headers={'content-length': '123'}, logger=logger) request.assert_called_with('http://127.0.0.1?format=json', - headers={}, + headers={'content-length': '123'}, data=None) self.assertEqual([None, None], retval) self.assertEqual('GET', request.return_value.get_method()) + self.assertEqual(logger.log_dict['debug'], [( + ('-> 2014-05-27T20:54:11 GET http://127.0.0.1%3Fformat%3Djson 200 ' + '123 345 1401224050.98 1401224051.98 1.0 -',), {})]) # Check if JSON is decoded urlopen.return_value.read.return_value = '{}' @@ -1021,7 +1039,7 @@ class TestSimpleClient(unittest.TestCase): # same as above, now with object name retval = sc.retry_request('GET', container='cont', name='obj') - request.assert_called_with('http://127.0.0.1/cont/obj?format=json', + request.assert_called_with('http://127.0.0.1/cont/obj', headers={'X-Auth-Token': 'token'}, data=None) self.assertEqual([None, {}], retval) diff --git a/test/unit/container/test_sync.py b/test/unit/container/test_sync.py index 0f45aa2acb..63f3eb92fe 100644 --- a/test/unit/container/test_sync.py +++ b/test/unit/container/test_sync.py @@ -640,8 +640,10 @@ class TestContainerSync(unittest.TestCase): hex = 'abcdef' sync.uuid = FakeUUID + fake_logger = FakeLogger() - def fake_delete_object(path, name=None, headers=None, proxy=None): + def fake_delete_object(path, name=None, headers=None, proxy=None, + logger=None): self.assertEquals(path, 'http://sync/to/path') self.assertEquals(name, 'object') if realm: @@ -654,10 +656,12 @@ class TestContainerSync(unittest.TestCase): headers, {'x-container-sync-key': 'key', 'x-timestamp': '1.2'}) self.assertEquals(proxy, 'http://proxy') + self.assertEqual(logger, fake_logger) sync.delete_object = fake_delete_object cs = sync.ContainerSync({}, container_ring=FakeRing(), object_ring=FakeRing()) + cs.logger = fake_logger cs.http_proxies = ['http://proxy'] # Success self.assertTrue(cs.container_sync_row( @@ -670,7 +674,7 @@ class TestContainerSync(unittest.TestCase): exc = [] - def fake_delete_object(path, name=None, headers=None, proxy=None): + def fake_delete_object(*args, **kwargs): exc.append(Exception('test exception')) raise exc[-1] @@ -686,7 +690,7 @@ class TestContainerSync(unittest.TestCase): self.assertEquals(len(exc), 1) self.assertEquals(str(exc[-1]), 'test exception') - def fake_delete_object(path, name=None, headers=None, proxy=None): + def fake_delete_object(*args, **kwargs): exc.append(ClientException('test client exception')) raise exc[-1] @@ -702,7 +706,7 @@ class TestContainerSync(unittest.TestCase): self.assertEquals(len(exc), 2) self.assertEquals(str(exc[-1]), 'test client exception') - def fake_delete_object(path, name=None, headers=None, proxy=None): + def fake_delete_object(*args, **kwargs): exc.append(ClientException('test client exception', http_status=404)) raise exc[-1] @@ -740,9 +744,10 @@ class TestContainerSync(unittest.TestCase): sync.uuid = FakeUUID sync.shuffle = lambda x: x + fake_logger = FakeLogger() def fake_put_object(sync_to, name=None, headers=None, - contents=None, proxy=None): + contents=None, proxy=None, logger=None): self.assertEquals(sync_to, 'http://sync/to/path') self.assertEquals(name, 'object') if realm: @@ -760,15 +765,16 @@ class TestContainerSync(unittest.TestCase): 'etag': 'etagvalue'}) self.assertEquals(contents.read(), 'contents') self.assertEquals(proxy, 'http://proxy') + self.assertEqual(logger, fake_logger) sync.put_object = fake_put_object cs = sync.ContainerSync({}, container_ring=FakeRing(), object_ring=FakeRing()) + cs.logger = fake_logger cs.http_proxies = ['http://proxy'] - def fake_direct_get_object(node, part, account, container, obj, - resp_chunk_size=1): + def fake_direct_get_object(*args, **kwargs): return ({'other-header': 'other header value', 'etag': '"etagvalue"', 'x-timestamp': '1.2'}, iter('contents')) @@ -784,8 +790,7 @@ class TestContainerSync(unittest.TestCase): 'container': 'c'}, realm, realm_key)) self.assertEquals(cs.container_puts, 1) - def fake_direct_get_object(node, part, account, container, obj, - resp_chunk_size=1): + def fake_direct_get_object(*args, **kwargs): return ({'date': 'date value', 'last-modified': 'last modified value', 'x-timestamp': '1.2', @@ -808,8 +813,7 @@ class TestContainerSync(unittest.TestCase): exc = [] - def fake_direct_get_object(node, part, account, container, obj, - resp_chunk_size=1): + def fake_direct_get_object(*args, **kwargs): exc.append(Exception('test exception')) raise exc[-1] @@ -828,8 +832,7 @@ class TestContainerSync(unittest.TestCase): exc = [] - def fake_direct_get_object(node, part, account, container, obj, - resp_chunk_size=1): + def fake_direct_get_object(*args, **kwargs): if len(exc) == 0: exc.append(Exception('test other exception')) else: @@ -851,14 +854,12 @@ class TestContainerSync(unittest.TestCase): self.assertEquals(str(exc[-2]), 'test client exception') self.assertEquals(str(exc[-1]), 'test client exception') - def fake_direct_get_object(node, part, account, container, obj, - resp_chunk_size=1): + def fake_direct_get_object(*args, **kwargs): return ({'other-header': 'other header value', 'x-timestamp': '1.2', 'etag': '"etagvalue"'}, iter('contents')) - def fake_put_object(sync_to, name=None, headers=None, - contents=None, proxy=None): + def fake_put_object(*args, **kwargs): raise ClientException('test client exception', http_status=401) sync.direct_get_object = fake_direct_get_object @@ -876,8 +877,7 @@ class TestContainerSync(unittest.TestCase): self.assert_(re.match('Unauth ', cs.logger.log_dict['info'][0][0][0])) - def fake_put_object(sync_to, name=None, headers=None, - contents=None, proxy=None): + def fake_put_object(*args, **kwargs): raise ClientException('test client exception', http_status=404) sync.put_object = fake_put_object @@ -894,8 +894,7 @@ class TestContainerSync(unittest.TestCase): self.assert_(re.match('Not found ', cs.logger.log_dict['info'][0][0][0])) - def fake_put_object(sync_to, name=None, headers=None, - contents=None, proxy=None): + def fake_put_object(*args, **kwargs): raise ClientException('test client exception', http_status=503) sync.put_object = fake_put_object