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
This commit is contained in:
gholt 2014-05-27 21:10:47 +00:00
parent 181e9496fa
commit 11bbc09bd7
4 changed files with 76 additions and 32 deletions

View File

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

View File

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

View File

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

View File

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