Merge "Log and report trace on service operation fails"

This commit is contained in:
Jenkins 2015-09-04 01:46:18 +00:00 committed by Gerrit Code Review
commit 93666bb84a
3 changed files with 241 additions and 61 deletions

View File

@ -12,7 +12,9 @@
# implied. # implied.
# See the License for the specific language governing permissions and # See the License for the specific language governing permissions and
# limitations under the License. # limitations under the License.
import logging
import os import os
from concurrent.futures import as_completed, CancelledError, TimeoutError from concurrent.futures import as_completed, CancelledError, TimeoutError
from copy import deepcopy from copy import deepcopy
from errno import EEXIST, ENOENT from errno import EEXIST, ENOENT
@ -39,12 +41,15 @@ from swiftclient.command_helpers import (
) )
from swiftclient.utils import ( from swiftclient.utils import (
config_true_value, ReadableToIterable, LengthWrapper, EMPTY_ETAG, config_true_value, ReadableToIterable, LengthWrapper, EMPTY_ETAG,
parse_api_response parse_api_response, report_traceback
) )
from swiftclient.exceptions import ClientException from swiftclient.exceptions import ClientException
from swiftclient.multithreading import MultiThreadingManager from swiftclient.multithreading import MultiThreadingManager
logger = logging.getLogger("swiftclient.service")
class ResultsIterator(Iterator): class ResultsIterator(Iterator):
def __init__(self, futures): def __init__(self, futures):
self.futures = interruptable_as_completed(futures) self.futures = interruptable_as_completed(futures)
@ -435,16 +440,24 @@ class SwiftService(object):
return res return res
except ClientException as err: except ClientException as err:
if err.http_status != 404: if err.http_status != 404:
traceback, err_time = report_traceback()
logger.exception(err)
res.update({ res.update({
'success': False, 'success': False,
'error': err 'error': err,
'traceback': traceback,
'error_timestamp': err_time
}) })
return res return res
raise SwiftError('Account not found', exc=err) raise SwiftError('Account not found', exc=err)
except Exception as err: except Exception as err:
traceback, err_time = report_traceback()
logger.exception(err)
res.update({ res.update({
'success': False, 'success': False,
'error': err 'error': err,
'traceback': traceback,
'error_timestamp': err_time
}) })
return res return res
else: else:
@ -467,17 +480,25 @@ class SwiftService(object):
return res return res
except ClientException as err: except ClientException as err:
if err.http_status != 404: if err.http_status != 404:
traceback, err_time = report_traceback()
logger.exception(err)
res.update({ res.update({
'success': False, 'success': False,
'error': err 'error': err,
'traceback': traceback,
'error_timestamp': err_time
}) })
return res return res
raise SwiftError('Container %r not found' % container, raise SwiftError('Container %r not found' % container,
container=container, exc=err) container=container, exc=err)
except Exception as err: except Exception as err:
traceback, err_time = report_traceback()
logger.exception(err)
res.update({ res.update({
'success': False, 'success': False,
'error': err 'error': err,
'traceback': traceback,
'error_timestamp': err_time
}) })
return res return res
else: else:
@ -506,9 +527,13 @@ class SwiftService(object):
}) })
return res return res
except Exception as err: except Exception as err:
traceback, err_time = report_traceback()
logger.exception(err)
res.update({ res.update({
'success': False, 'success': False,
'error': err 'error': err,
'traceback': traceback,
'error_timestamp': err_time
}) })
return res return res
@ -581,18 +606,26 @@ class SwiftService(object):
get_future_result(post) get_future_result(post)
except ClientException as err: except ClientException as err:
if err.http_status != 404: if err.http_status != 404:
traceback, err_time = report_traceback()
logger.exception(err)
res.update({ res.update({
'success': False, 'success': False,
'error': err, 'error': err,
'traceback': traceback,
'error_timestamp': err_time,
'response_dict': response_dict 'response_dict': response_dict
}) })
return res return res
raise SwiftError('Account not found') raise SwiftError('Account not found', exc=err)
except Exception as err: except Exception as err:
traceback, err_time = report_traceback()
logger.exception(err)
res.update({ res.update({
'success': False, 'success': False,
'error': err, 'error': err,
'response_dict': response_dict 'response_dict': response_dict,
'traceback': traceback,
'error_timestamp': err_time
}) })
return res return res
if not objects: if not objects:
@ -619,23 +652,31 @@ class SwiftService(object):
get_future_result(post) get_future_result(post)
except ClientException as err: except ClientException as err:
if err.http_status != 404: if err.http_status != 404:
traceback, err_time = report_traceback()
logger.exception(err)
res.update({ res.update({
'action': 'post_container', 'action': 'post_container',
'success': False, 'success': False,
'error': err, 'error': err,
'traceback': traceback,
'error_timestamp': err_time,
'response_dict': response_dict 'response_dict': response_dict
}) })
return res return res
raise SwiftError( raise SwiftError(
"Container '%s' not found" % container, "Container '%s' not found" % container,
container=container container=container, exc=err
) )
except Exception as err: except Exception as err:
traceback, err_time = report_traceback()
logger.exception(err)
res.update({ res.update({
'action': 'post_container', 'action': 'post_container',
'success': False, 'success': False,
'error': err, 'error': err,
'response_dict': response_dict 'response_dict': response_dict,
'traceback': traceback,
'error_timestamp': err_time
}) })
return res return res
else: else:
@ -720,9 +761,13 @@ class SwiftService(object):
conn.post_object( conn.post_object(
container, obj, headers=headers, response_dict=result) container, obj, headers=headers, response_dict=result)
except Exception as err: except Exception as err:
traceback, err_time = report_traceback()
logger.exception(err)
res.update({ res.update({
'success': False, 'success': False,
'error': err 'error': err,
'traceback': traceback,
'error_timestamp': err_time
}) })
return res return res
@ -775,7 +820,6 @@ class SwiftService(object):
@staticmethod @staticmethod
def _list_account_job(conn, options, result_queue): def _list_account_job(conn, options, result_queue):
marker = '' marker = ''
success = True
error = None error = None
try: try:
while True: while True:
@ -804,23 +848,30 @@ class SwiftService(object):
marker = items[-1].get('name', items[-1].get('subdir')) marker = items[-1].get('name', items[-1].get('subdir'))
except ClientException as err: except ClientException as err:
success = False traceback, err_time = report_traceback()
logger.exception(err)
if err.http_status != 404: if err.http_status != 404:
error = err error = (err, traceback, err_time)
else: else:
error = SwiftError('Account not found') error = (
SwiftError('Account not found', exc=err),
traceback, err_time
)
except Exception as err: except Exception as err:
success = False traceback, err_time = report_traceback()
error = err logger.exception(err)
error = (err, traceback, err_time)
res = { res = {
'action': 'list_account_part', 'action': 'list_account_part',
'container': None, 'container': None,
'prefix': options['prefix'], 'prefix': options['prefix'],
'success': success, 'success': False,
'marker': marker, 'marker': marker,
'error': error, 'error': error[0],
'traceback': error[1],
'error_timestamp': error[2]
} }
result_queue.put(res) result_queue.put(res)
result_queue.put(None) result_queue.put(None)
@ -828,7 +879,6 @@ class SwiftService(object):
@staticmethod @staticmethod
def _list_container_job(conn, container, options, result_queue): def _list_container_job(conn, container, options, result_queue):
marker = '' marker = ''
success = True
error = None error = None
try: try:
while True: while True:
@ -853,23 +903,33 @@ class SwiftService(object):
marker = items[-1].get('name', items[-1].get('subdir')) marker = items[-1].get('name', items[-1].get('subdir'))
except ClientException as err: except ClientException as err:
success = False traceback, err_time = report_traceback()
logger.exception(err)
if err.http_status != 404: if err.http_status != 404:
error = err error = (err, traceback, err_time)
else: else:
error = SwiftError('Container %r not found' % container, error = (
container=container) SwiftError(
'Container %r not found' % container,
container=container, exc=err
),
traceback,
err_time
)
except Exception as err: except Exception as err:
success = False traceback, err_time = report_traceback()
error = err logger.exception(err)
error = (err, traceback, err_time)
res = { res = {
'action': 'list_container_part', 'action': 'list_container_part',
'container': container, 'container': container,
'prefix': options['prefix'], 'prefix': options['prefix'],
'success': success, 'success': False,
'marker': marker, 'marker': marker,
'error': error, 'error': error[0],
'traceback': error[1],
'error_timestamp': error[2]
} }
result_queue.put(res) result_queue.put(res)
result_queue.put(None) result_queue.put(None)
@ -937,7 +997,7 @@ class SwiftService(object):
except ClientException as err: except ClientException as err:
if err.http_status != 404: if err.http_status != 404:
raise raise
raise SwiftError('Account not found') raise SwiftError('Account not found', exc=err)
elif not objects: elif not objects:
if '/' in container: if '/' in container:
@ -1123,12 +1183,16 @@ class SwiftService(object):
return res return res
except Exception as err: except Exception as err:
traceback, err_time = report_traceback()
logger.exception(err)
res = { res = {
'action': 'download_object', 'action': 'download_object',
'container': container, 'container': container,
'object': obj, 'object': obj,
'success': False, 'success': False,
'error': err, 'error': err,
'traceback': traceback,
'error_timestamp': err_time,
'response_dict': results_dict, 'response_dict': results_dict,
'path': path, 'path': path,
'pseudodir': pseudodir, 'pseudodir': pseudodir,
@ -1168,7 +1232,8 @@ class SwiftService(object):
if err.http_status != 404: if err.http_status != 404:
raise raise
raise SwiftError( raise SwiftError(
'Container %r not found' % container, container=container 'Container %r not found' % container,
container=container, exc=err
) )
error = None error = None
@ -1195,6 +1260,7 @@ class SwiftService(object):
) )
except ClientException as err: except ClientException as err:
# Allow the current page to finish downloading # Allow the current page to finish downloading
logger.exception(err)
error = err error = err
except Exception: except Exception:
# Something unexpected went wrong - cancel # Something unexpected went wrong - cancel
@ -1368,12 +1434,16 @@ class SwiftService(object):
file_jobs[file_future] = details file_jobs[file_future] = details
except OSError as err: except OSError as err:
# Avoid tying up threads with jobs that will fail # Avoid tying up threads with jobs that will fail
traceback, err_time = report_traceback()
logger.exception(err)
res = { res = {
'action': 'upload_object', 'action': 'upload_object',
'container': container, 'container': container,
'object': o, 'object': o,
'success': False, 'success': False,
'error': err, 'error': err,
'traceback': traceback,
'error_timestamp': err_time,
'path': s 'path': s
} }
rq.put(res) rq.put(res)
@ -1472,9 +1542,13 @@ class SwiftService(object):
'response_dict': create_response 'response_dict': create_response
}) })
except Exception as err: except Exception as err:
traceback, err_time = report_traceback()
logger.exception(err)
res.update({ res.update({
'success': False, 'success': False,
'error': err, 'error': err,
'traceback': traceback,
'error_timestamp': err_time,
'response_dict': create_response 'response_dict': create_response
}) })
return res return res
@ -1513,9 +1587,14 @@ class SwiftService(object):
return res return res
except ClientException as err: except ClientException as err:
if err.http_status != 404: if err.http_status != 404:
traceback, err_time = report_traceback()
logger.exception(err)
res.update({ res.update({
'success': False, 'success': False,
'error': err}) 'error': err,
'traceback': traceback,
'error_timestamp': err_time
})
return res return res
try: try:
conn.put_object(container, obj, '', content_length=0, conn.put_object(container, obj, '', content_length=0,
@ -1527,9 +1606,13 @@ class SwiftService(object):
'response_dict': results_dict}) 'response_dict': results_dict})
return res return res
except Exception as err: except Exception as err:
traceback, err_time = report_traceback()
logger.exception(err)
res.update({ res.update({
'success': False, 'success': False,
'error': err, 'error': err,
'traceback': traceback,
'error_timestamp': err_time,
'response_dict': results_dict}) 'response_dict': results_dict})
return res return res
@ -1582,9 +1665,13 @@ class SwiftService(object):
return res return res
except Exception as err: except Exception as err:
traceback, err_time = report_traceback()
logger.exception(err)
res.update({ res.update({
'success': False, 'success': False,
'error': err, 'error': err,
'traceback': traceback,
'error_timestamp': err_time,
'response_dict': results_dict, 'response_dict': results_dict,
'attempts': conn.attempts 'attempts': conn.attempts
}) })
@ -1713,9 +1800,13 @@ class SwiftService(object):
old_slo_manifest_paths.append(seg_path) old_slo_manifest_paths.append(seg_path)
except ClientException as err: except ClientException as err:
if err.http_status != 404: if err.http_status != 404:
traceback, err_time = report_traceback()
logger.exception(err)
res.update({ res.update({
'success': False, 'success': False,
'error': err 'error': err,
'traceback': traceback,
'error_timestamp': err_time
}) })
return res return res
@ -1770,9 +1861,11 @@ class SwiftService(object):
if not r['success']: if not r['success']:
errors = True errors = True
segment_results.append(r) segment_results.append(r)
except Exception as e: except Exception as err:
traceback, err_time = report_traceback()
logger.exception(err)
errors = True errors = True
exceptions.append(e) exceptions.append((err, traceback, err_time))
if errors: if errors:
err = ClientException( err = ClientException(
'Aborting manifest creation ' 'Aborting manifest creation '
@ -1901,16 +1994,26 @@ class SwiftService(object):
return res return res
except OSError as err: except OSError as err:
traceback, err_time = report_traceback()
logger.exception(err)
if err.errno == ENOENT: if err.errno == ENOENT:
err = SwiftError('Local file %r not found' % path) error = SwiftError('Local file %r not found' % path, exc=err)
else:
error = err
res.update({ res.update({
'success': False, 'success': False,
'error': err 'error': error,
'traceback': traceback,
'error_timestamp': err_time
}) })
except Exception as err: except Exception as err:
traceback, err_time = report_traceback()
logger.exception(err)
res.update({ res.update({
'success': False, 'success': False,
'error': err 'error': err,
'traceback': traceback,
'error_timestamp': err_time
}) })
return res return res
@ -2009,8 +2112,15 @@ class SwiftService(object):
try: try:
conn.delete_object(container, obj, response_dict=results_dict) conn.delete_object(container, obj, response_dict=results_dict)
res = {'success': True} res = {'success': True}
except Exception as e: except Exception as err:
res = {'success': False, 'error': e} traceback, err_time = report_traceback()
logger.exception(err)
res = {
'success': False,
'error': err,
'traceback': traceback,
'error_timestamp': err_time
}
res.update({ res.update({
'action': 'delete_segment', 'action': 'delete_segment',
@ -2026,12 +2136,12 @@ class SwiftService(object):
def _delete_object(self, conn, container, obj, options, def _delete_object(self, conn, container, obj, options,
results_queue=None): results_queue=None):
res = {
'action': 'delete_object',
'container': container,
'object': obj
}
try: try:
res = {
'action': 'delete_object',
'container': container,
'object': obj
}
old_manifest = None old_manifest = None
query_string = None query_string = None
@ -2086,8 +2196,14 @@ class SwiftService(object):
}) })
except Exception as err: except Exception as err:
res['success'] = False traceback, err_time = report_traceback()
res['error'] = err logger.exception(err)
res.update({
'success': False,
'error': err,
'traceback': traceback,
'error_timestamp': err_time
})
return res return res
return res return res
@ -2098,8 +2214,15 @@ class SwiftService(object):
try: try:
conn.delete_container(container, response_dict=results_dict) conn.delete_container(container, response_dict=results_dict)
res = {'success': True} res = {'success': True}
except Exception as e: except Exception as err:
res = {'success': False, 'error': e} traceback, err_time = report_traceback()
logger.exception(err)
res = {
'success': False,
'error': err,
'traceback': traceback,
'error_timestamp': err_time
}
res.update({ res.update({
'action': 'delete_container', 'action': 'delete_container',
@ -2130,12 +2253,16 @@ class SwiftService(object):
con_del_res = get_future_result(con_del) con_del_res = get_future_result(con_del)
except Exception as err: except Exception as err:
traceback, err_time = report_traceback()
logger.exception(err)
con_del_res = { con_del_res = {
'action': 'delete_container', 'action': 'delete_container',
'container': container, 'container': container,
'object': None, 'object': None,
'success': False, 'success': False,
'error': err 'error': err,
'traceback': traceback,
'error_timestamp': err_time
} }
yield con_del_res yield con_del_res
@ -2173,7 +2300,7 @@ class SwiftService(object):
except ClientException as err: except ClientException as err:
if err.http_status != 404: if err.http_status != 404:
raise err raise err
raise SwiftError('Account not found') raise SwiftError('Account not found', exc=err)
return res return res
@ -2208,10 +2335,16 @@ class SwiftService(object):
res['status'] = 'cancelled' res['status'] = 'cancelled'
result_queue.put(res) result_queue.put(res)
except Exception as err: except Exception as err:
traceback, err_time = report_traceback()
logger.exception(err)
details = futures[f] details = futures[f]
res = details res = details
res['success'] = False res.update({
res['error'] = err 'success': False,
'error': err,
'traceback': traceback,
'error_timestamp': err_time
})
result_queue.put(res) result_queue.put(res)
result_queue.put(None) result_queue.put(None)

View File

@ -17,9 +17,9 @@ import hashlib
import hmac import hmac
import json import json
import logging import logging
import time
import six import six
import time
import traceback
TRUE_VALUES = set(('true', '1', 'yes', 'on', 't', 'y')) TRUE_VALUES = set(('true', '1', 'yes', 'on', 't', 'y'))
EMPTY_ETAG = 'd41d8cd98f00b204e9800998ecf8427e' EMPTY_ETAG = 'd41d8cd98f00b204e9800998ecf8427e'
@ -119,6 +119,20 @@ def parse_api_response(headers, body):
return json.loads(body.decode(charset)) return json.loads(body.decode(charset))
def report_traceback():
"""
Reports a timestamp and full traceback for a given exception.
:return: Full traceback and timestamp.
"""
try:
formatted_lines = traceback.format_exc()
now = time.time()
return formatted_lines, now
except AttributeError:
return None, None
class NoopMD5(object): class NoopMD5(object):
def __init__(self, *a, **kw): def __init__(self, *a, **kw):
pass pass

View File

@ -232,16 +232,23 @@ class TestServiceDelete(_TestServiceBase):
'action': 'delete_segment', 'action': 'delete_segment',
'object': 'test_s', 'object': 'test_s',
'success': False, 'success': False,
'error': self.exc 'error': self.exc,
'traceback': mock.ANY,
'error_timestamp': mock.ANY
}) })
before = time.time()
r = SwiftService._delete_segment(mock_conn, 'test_c', 'test_s', mock_q) r = SwiftService._delete_segment(mock_conn, 'test_c', 'test_s', mock_q)
after = time.time()
mock_conn.delete_object.assert_called_once_with( mock_conn.delete_object.assert_called_once_with(
'test_c', 'test_s', response_dict={} 'test_c', 'test_s', response_dict={}
) )
self._assertDictEqual(expected_r, r) self._assertDictEqual(expected_r, r)
self._assertDictEqual(expected_r, self._get_queue(mock_q)) self._assertDictEqual(expected_r, self._get_queue(mock_q))
self.assertGreaterEqual(r['error_timestamp'], before)
self.assertLessEqual(r['error_timestamp'], after)
self.assertTrue('Traceback' in r['traceback'])
def test_delete_object(self): def test_delete_object(self):
mock_q = Queue() mock_q = Queue()
@ -268,20 +275,27 @@ class TestServiceDelete(_TestServiceBase):
expected_r = self._get_expected({ expected_r = self._get_expected({
'action': 'delete_object', 'action': 'delete_object',
'success': False, 'success': False,
'error': self.exc 'error': self.exc,
'traceback': mock.ANY,
'error_timestamp': mock.ANY
}) })
# _delete_object doesnt populate attempts or response dict if it hits # _delete_object doesnt populate attempts or response dict if it hits
# an error. This may not be the correct behaviour. # an error. This may not be the correct behaviour.
del expected_r['response_dict'], expected_r['attempts'] del expected_r['response_dict'], expected_r['attempts']
before = time.time()
s = SwiftService() s = SwiftService()
r = s._delete_object(mock_conn, 'test_c', 'test_o', self.opts, mock_q) r = s._delete_object(mock_conn, 'test_c', 'test_o', self.opts, mock_q)
after = time.time()
mock_conn.head_object.assert_called_once_with('test_c', 'test_o') mock_conn.head_object.assert_called_once_with('test_c', 'test_o')
mock_conn.delete_object.assert_called_once_with( mock_conn.delete_object.assert_called_once_with(
'test_c', 'test_o', query_string=None, response_dict={} 'test_c', 'test_o', query_string=None, response_dict={}
) )
self._assertDictEqual(expected_r, r) self._assertDictEqual(expected_r, r)
self.assertGreaterEqual(r['error_timestamp'], before)
self.assertLessEqual(r['error_timestamp'], after)
self.assertTrue('Traceback' in r['traceback'])
def test_delete_object_slo_support(self): def test_delete_object_slo_support(self):
# If SLO headers are present the delete call should include an # If SLO headers are present the delete call should include an
@ -358,23 +372,30 @@ class TestServiceDelete(_TestServiceBase):
) )
self._assertDictEqual(expected_r, r) self._assertDictEqual(expected_r, r)
def test_delete_empty_container_excpetion(self): def test_delete_empty_container_exception(self):
mock_conn = self._get_mock_connection() mock_conn = self._get_mock_connection()
mock_conn.delete_container = Mock(side_effect=self.exc) mock_conn.delete_container = Mock(side_effect=self.exc)
expected_r = self._get_expected({ expected_r = self._get_expected({
'action': 'delete_container', 'action': 'delete_container',
'success': False, 'success': False,
'object': None, 'object': None,
'error': self.exc 'error': self.exc,
'traceback': mock.ANY,
'error_timestamp': mock.ANY
}) })
before = time.time()
s = SwiftService() s = SwiftService()
r = s._delete_empty_container(mock_conn, 'test_c') r = s._delete_empty_container(mock_conn, 'test_c')
after = time.time()
mock_conn.delete_container.assert_called_once_with( mock_conn.delete_container.assert_called_once_with(
'test_c', response_dict={} 'test_c', response_dict={}
) )
self._assertDictEqual(expected_r, r) self._assertDictEqual(expected_r, r)
self.assertGreaterEqual(r['error_timestamp'], before)
self.assertLessEqual(r['error_timestamp'], after)
self.assertTrue('Traceback' in r['traceback'])
class TestSwiftError(testtools.TestCase): class TestSwiftError(testtools.TestCase):
@ -623,7 +644,9 @@ class TestServiceList(_TestServiceBase):
'action': 'list_account_part', 'action': 'list_account_part',
'success': False, 'success': False,
'error': self.exc, 'error': self.exc,
'marker': '' 'marker': '',
'traceback': mock.ANY,
'error_timestamp': mock.ANY
}) })
SwiftService._list_account_job( SwiftService._list_account_job(
@ -689,7 +712,9 @@ class TestServiceList(_TestServiceBase):
'container': 'test_c', 'container': 'test_c',
'success': False, 'success': False,
'error': self.exc, 'error': self.exc,
'marker': '' 'marker': '',
'error_timestamp': mock.ANY,
'traceback': mock.ANY
}) })
SwiftService._list_container_job( SwiftService._list_container_job(
@ -1446,7 +1471,9 @@ class TestServiceDownload(_TestServiceBase):
mock_conn.get_object = Mock(side_effect=self.exc) mock_conn.get_object = Mock(side_effect=self.exc)
expected_r = self._get_expected({ expected_r = self._get_expected({
'success': False, 'success': False,
'error': self.exc 'error': self.exc,
'error_timestamp': mock.ANY,
'traceback': mock.ANY
}) })
s = SwiftService() s = SwiftService()
@ -1581,6 +1608,8 @@ class TestServiceDownload(_TestServiceBase):
'path': 'test_o', 'path': 'test_o',
'pseudodir': False, 'pseudodir': False,
'attempts': 2, 'attempts': 2,
'traceback': mock.ANY,
'error_timestamp': mock.ANY
} }
s = SwiftService() s = SwiftService()
@ -1634,6 +1663,8 @@ class TestServiceDownload(_TestServiceBase):
'path': 'test_o', 'path': 'test_o',
'pseudodir': False, 'pseudodir': False,
'attempts': 2, 'attempts': 2,
'traceback': mock.ANY,
'error_timestamp': mock.ANY
} }
s = SwiftService() s = SwiftService()
@ -1715,6 +1746,8 @@ class TestServiceDownload(_TestServiceBase):
'path': 'test_o', 'path': 'test_o',
'pseudodir': False, 'pseudodir': False,
'attempts': 2, 'attempts': 2,
'traceback': mock.ANY,
'error_timestamp': mock.ANY
} }
s = SwiftService() s = SwiftService()