Log and report trace on service operation fails

This patch adds exception logging to the swift service API. Each
operation that results in failure of any operation will now log
the exception as well as report a timestamp and full stack trace
in the results returned by the service API calls.

Change-Id: I7336b28354e7740ea7d048bdf355e3c1a1b4436c
This commit is contained in:
Joel Wright 2015-04-05 16:48:34 +01:00
parent e52df5d8a5
commit 3c0289844f
3 changed files with 241 additions and 61 deletions

View File

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

View File

@ -17,9 +17,9 @@ import hashlib
import hmac
import json
import logging
import time
import six
import time
import traceback
TRUE_VALUES = set(('true', '1', 'yes', 'on', 't', 'y'))
EMPTY_ETAG = 'd41d8cd98f00b204e9800998ecf8427e'
@ -119,6 +119,20 @@ def parse_api_response(headers, body):
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):
def __init__(self, *a, **kw):
pass

View File

@ -227,16 +227,23 @@ class TestServiceDelete(_TestServiceBase):
'action': 'delete_segment',
'object': 'test_s',
'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)
after = time.time()
mock_conn.delete_object.assert_called_once_with(
'test_c', 'test_s', response_dict={}
)
self._assertDictEqual(expected_r, r)
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):
mock_q = Queue()
@ -263,20 +270,27 @@ class TestServiceDelete(_TestServiceBase):
expected_r = self._get_expected({
'action': 'delete_object',
'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
# an error. This may not be the correct behaviour.
del expected_r['response_dict'], expected_r['attempts']
before = time.time()
s = SwiftService()
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.delete_object.assert_called_once_with(
'test_c', 'test_o', query_string=None, response_dict={}
)
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):
# If SLO headers are present the delete call should include an
@ -353,23 +367,30 @@ class TestServiceDelete(_TestServiceBase):
)
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.delete_container = Mock(side_effect=self.exc)
expected_r = self._get_expected({
'action': 'delete_container',
'success': False,
'object': None,
'error': self.exc
'error': self.exc,
'traceback': mock.ANY,
'error_timestamp': mock.ANY
})
before = time.time()
s = SwiftService()
r = s._delete_empty_container(mock_conn, 'test_c')
after = time.time()
mock_conn.delete_container.assert_called_once_with(
'test_c', response_dict={}
)
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):
@ -618,7 +639,9 @@ class TestServiceList(_TestServiceBase):
'action': 'list_account_part',
'success': False,
'error': self.exc,
'marker': ''
'marker': '',
'traceback': mock.ANY,
'error_timestamp': mock.ANY
})
SwiftService._list_account_job(
@ -684,7 +707,9 @@ class TestServiceList(_TestServiceBase):
'container': 'test_c',
'success': False,
'error': self.exc,
'marker': ''
'marker': '',
'error_timestamp': mock.ANY,
'traceback': mock.ANY
})
SwiftService._list_container_job(
@ -1431,7 +1456,9 @@ class TestServiceDownload(_TestServiceBase):
mock_conn.get_object = Mock(side_effect=self.exc)
expected_r = self._get_expected({
'success': False,
'error': self.exc
'error': self.exc,
'error_timestamp': mock.ANY,
'traceback': mock.ANY
})
s = SwiftService()
@ -1566,6 +1593,8 @@ class TestServiceDownload(_TestServiceBase):
'path': 'test_o',
'pseudodir': False,
'attempts': 2,
'traceback': mock.ANY,
'error_timestamp': mock.ANY
}
s = SwiftService()
@ -1619,6 +1648,8 @@ class TestServiceDownload(_TestServiceBase):
'path': 'test_o',
'pseudodir': False,
'attempts': 2,
'traceback': mock.ANY,
'error_timestamp': mock.ANY
}
s = SwiftService()
@ -1700,6 +1731,8 @@ class TestServiceDownload(_TestServiceBase):
'path': 'test_o',
'pseudodir': False,
'attempts': 2,
'traceback': mock.ANY,
'error_timestamp': mock.ANY
}
s = SwiftService()