Merge lp:~thomir-deactivatedaccount/uservice-utils/trunk-add-exception-logging into lp:uservice-utils

[Thomi Richards]

Log full exception tracebacks on uncaught exceptions in the queue worker.

Format uncaught exceptions better.

[Celso Providelo (cprov)]

Thomi,

Thanks for including traceback on error messages, they will be useful in logstash.

I don't really get the reason beyond the tests redesign apart from incorporating the retry policy mechanism. Maybe I am missing something ? Either way I am happy if tarmac like them.

review: Approve

=== modified file 'uservice_utils/queue.py'
--- uservice_utils/queue.py	2015-04-02 19:28:58 +0000
+++ uservice_utils/queue.py	2015-04-07 23:22:42 +0000
@@ -21,6 +21,15 @@
 import logging
 from pdb import bdb
 
+# Traceback2 contains back-ported functionality that will appear in python
+# version 3.5. Specifically, tracebacks will have stack-locals printed in
+# them. This is useful, but we can't rely on it being installed. Try and
+# import the new version, but fall back to the old if it's not present.
+try:
+    import traceback2 as traceback
+except ImportError:
+    import traceback
+
 import kombu
 from kombu.mixins import ConsumerMixin
 
@@ -119,10 +128,10 @@
         # Make it possible to use a debugger inside the worker callback:
         except bdb.BdbQuit:
             raise
-        except Exception as e:
+        except Exception:
             logger.error(
-                "Caught unhandled exception while processing message: %s",
-                e,
+                "Caught unhandled exception while processing message:\n%s",
+                traceback.format_exc(),
             )
             self.retry_policy.retry(self.connection, message)
 

=== modified file 'uservice_utils/tests/test_queue.py'
--- uservice_utils/tests/test_queue.py	2015-04-02 19:28:58 +0000
+++ uservice_utils/tests/test_queue.py	2015-04-07 23:22:42 +0000
@@ -17,10 +17,10 @@
 
 """Integration tests for the kombu queue code."""
 
+from fixtures import FakeLogger
 import kombu
 import kombu.simple
 from testtools import TestCase
-
 from testtools.matchers import (
     Contains,
     Equals,
@@ -36,63 +36,74 @@
 
 class KombuQueueIntegrationTests(TestCase):
 
+    def setUp(self):
+        super().setUp()
+        self.message = {'test': self.getUniqueString()}
+
+    def create_worker(self, consumer, retry_policy=None):
+        conn = kombu.Connection('memory:///')
+        queue_name = self.getUniqueString()
+        queue_message(conn, queue_name, self.message)
+        retry_policy = retry_policy or LoggingRetryPolicy()
+
+        return SimpleRabbitQueueWorker(
+            conn,
+            queue_name,
+            consumer,
+            retry_policy,
+        )
+
     def test_can_read_and_accept_message(self):
-        conn = kombu.Connection('memory:///')
-        queue_name = self.getUniqueString()
-        queue_message(conn, queue_name, {'test': 'value'})
-        retry_policy = LoggingRetryPolicy()
-
         consumer = LoggingConsumer(MessageActions.Acknowledge)
-        q = SimpleRabbitQueueWorker(
-            conn,
-            queue_name,
-            consumer,
-            retry_policy,
-        )
+        retry_policy = LoggingRetryPolicy()
+        q = self.create_worker(consumer, retry_policy)
+
         # pump the queue to get the enqueued message:
         next(q.consume(limit=1, timeout=5.0))
 
-        self.assertEqual(consumer.got_messages, [dict(test='value')])
+        self.assertEqual(consumer.got_messages, [self.message])
         self.assertEqual(retry_policy.payloads_retried, [])
 
     def test_uncaught_exceptions_cause_message_retry(self):
-        conn = kombu.Connection('memory:///')
-        queue_name = self.getUniqueString()
-        message = {'test': 'value'}
-        queue_message(conn, queue_name, message)
-        retry_policy = LoggingRetryPolicy()
-
         def consumer_with_bug(message):
             raise RuntimeError("I am a bug, all up in ur bizniz!")
-        queue = SimpleRabbitQueueWorker(
-            conn,
-            queue_name,
-            consumer_with_bug,
-            retry_policy
-        )
-        next(queue.consume(limit=1, timeout=5.0))
-
-        self.assertEqual(retry_policy.payloads_retried, [message])
+        retry_policy = LoggingRetryPolicy()
+
+        queue = self.create_worker(consumer_with_bug, retry_policy)
+        # supress the logged message:
+        with FakeLogger():
+            next(queue.consume(limit=1, timeout=5.0))
+
+        self.assertEqual(retry_policy.payloads_retried, [self.message])
 
     def test_retry_message_works(self):
-        conn = kombu.Connection('memory:///')
-        queue_name = self.getUniqueString()
-        message = {'test': 'value'}
-        queue_message(conn, queue_name, message)
-        retry_policy = LoggingRetryPolicy()
-
         consumer = LoggingConsumer(MessageActions.Retry)
-        q = SimpleRabbitQueueWorker(
-            conn,
-            queue_name,
-            consumer,
-            retry_policy,
-        )
+        retry_policy = LoggingRetryPolicy()
+
+        q = self.create_worker(consumer, retry_policy)
         # pump the queue to get the enqueued message:
         next(q.consume(limit=1, timeout=5.0))
 
-        self.assertEqual(consumer.got_messages, [message])
-        self.assertEqual(retry_policy.payloads_retried, [message])
+        self.assertEqual(consumer.got_messages, [self.message])
+        self.assertEqual(retry_policy.payloads_retried, [self.message])
+
+    def test_unhandled_exceptions_cause_full_traceback(self):
+        def consumer_with_bug(message):
+            raise RuntimeError("I am a bug, all up in ur bizniz!")
+        retry_policy = LoggingRetryPolicy()
+        queue = self.create_worker(consumer_with_bug, retry_policy)
+        # supress the logged message:
+        with FakeLogger() as f:
+            next(queue.consume(limit=1, timeout=5.0))
+            log_contents = f.output
+            # must contain the exception line...
+            self.assertThat(log_contents, Contains("I am a bug, all up in ur bizniz!"))
+            # and also the traceback (search for this file, since it will be
+            # the top of the tracback)
+            self.assertThat(log_contents, Contains(__file__))
+
+        self.assertEqual(retry_policy.payloads_retried, [self.message])
+
 
 
 class DefaultRetryPolicyTests(TestCase):
@@ -143,7 +154,9 @@
         )
         policy = DefaultRetryPolicy(max_retries=0, dead_queue=dead_queue)
 
-        policy.retry(conn, message)
+        # supress the logged message:
+        with FakeLogger():
+            policy.retry(conn, message)
 
         # make sure the input message was dealt with:
         self.assertTrue(message.acknowledged)