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

3 files changed, 241 insertions, 61 deletions

diff --git a/swiftclient/service.py b/swiftclient/service.py
index 4f331c4..c013b90 100644
--- a/swiftclient/service.py
+++ b/swiftclient/service.py
@@ -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)
diff --git a/swiftclient/utils.py b/swiftclient/utils.py
index 8edfcfa..6ff6259 100644
--- a/swiftclient/utils.py
+++ b/swiftclient/utils.py
@@ -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
diff --git a/tests/unit/test_service.py b/tests/unit/test_service.py
index db47263..715a7b7 100644
--- a/tests/unit/test_service.py
+++ b/tests/unit/test_service.py
@@ -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()