Merge "Log and report trace on service operation fails"

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 d47c382..976d346 100644
--- a/tests/unit/test_service.py
+++ b/tests/unit/test_service.py
@@ -232,16 +232,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()
@@ -268,20 +275,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
@@ -358,23 +372,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):
@@ -623,7 +644,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(
@@ -689,7 +712,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(
@@ -1446,7 +1471,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()
@@ -1581,6 +1608,8 @@ class TestServiceDownload(_TestServiceBase):
                 'path': 'test_o',
                 'pseudodir': False,
                 'attempts': 2,
+                'traceback': mock.ANY,
+                'error_timestamp': mock.ANY
             }
 
             s = SwiftService()
@@ -1634,6 +1663,8 @@ class TestServiceDownload(_TestServiceBase):
                 'path': 'test_o',
                 'pseudodir': False,
                 'attempts': 2,
+                'traceback': mock.ANY,
+                'error_timestamp': mock.ANY
             }
 
             s = SwiftService()
@@ -1715,6 +1746,8 @@ class TestServiceDownload(_TestServiceBase):
                 'path': 'test_o',
                 'pseudodir': False,
                 'attempts': 2,
+                'traceback': mock.ANY,
+                'error_timestamp': mock.ANY
             }
 
             s = SwiftService()