Repository: simphony/simphony-remote

Issue:
Formalise error handling with the logger and the refnumber for the issue
Currently when an error takes place in a number of places we generate a `refnumber` that can be displayed in the user when an error takes place. This `refnumber` is at the same time logged next to the related error. This will help to pinpoint the place in the logs where a specific error (reported by a user) took place and simplify debugging.

To achieve this I would suggest one of the following:

- Wrap the python `Logger`  logging functions so that they generate a refnumber, pass it to the logger and then return it to the caller.
- Provide a generic `log(self, level, msg, *args, **kwargs)` function in the `BaseHandler` that will generate the refnumber pass it to a python logger and return it.

I think that the second implementation is simpler and easier to test. 



Discussion:

Patch:
diff --git a/remoteappmanager/handlers/home_handler.py b/remoteappmanager/handlers/home_handler.py
index c1648de..5b50efc 100644
--- a/remoteappmanager/handlers/home_handler.py
+++ b/remoteappmanager/handlers/home_handler.py
@@ -1,6 +1,5 @@
 import socket
 import os
-import uuid
 from datetime import timedelta
 
 import errno
@@ -45,12 +44,11 @@ class HomeHandler(BaseHandler):
 
         try:
             yield handler(options)
-        except Exception as e:
+        except Exception as exc:
             # Create a random reference number for support
-            ref = str(uuid.uuid1())
-            self.log.exception("Failed with POST action: {0}. {1} "
-                               "Ref: {2}".format(
-                                   action, str(e), ref))
+            ref = self.log.issue(
+                "Failed with POST action {}".format(action),
+                exc)
 
             images_info = yield self._get_images_info()
 
@@ -63,7 +61,7 @@ class HomeHandler(BaseHandler):
                         images_info=images_info,
                         error_message=message.format(
                             action=action,
-                            error_type=type(e).__name__,
+                            error_type=type(exc).__name__,
                             ref=ref))
 
     # Subhandling after post
diff --git a/remoteappmanager/logging/logging_mixin.py b/remoteappmanager/logging/logging_mixin.py
index 6339a43..fddc6f6 100644
--- a/remoteappmanager/logging/logging_mixin.py
+++ b/remoteappmanager/logging/logging_mixin.py
@@ -1,3 +1,6 @@
+import uuid
+import types
+
 from traitlets import (
     HasTraits,
     Instance,
@@ -5,6 +8,25 @@ from traitlets import (
 )
 
 
+def issue(self, message, exc=None):
+    """Accepts a message that will be logged with an additional reference
+    code for easy log lookup.
+
+    The identifier will be returned for inclusion in user-visible
+    error messages.
+    """
+    ref = str(uuid.uuid1())
+
+    if exc is None:
+        err_message = "{}. Ref: {}".format(message, ref)
+    else:
+        err_message = "{} : {}. Ref: {}".format(
+            message, str(exc), ref)
+
+    self.error(err_message)
+    return ref
+
+
 class LoggingMixin(HasTraits):
     """A HasTrait class that provides logging. Used as a mixin.
     """
@@ -13,5 +35,9 @@ class LoggingMixin(HasTraits):
 
     @default('log')
     def _log_default(self):
-        from traitlets import log
-        return log.get_logger()
+        from tornado.log import app_log
+
+        # monkey patch the logger to provide an additional method that handles
+        # issues
+        app_log.issue = types.MethodType(issue, app_log)
+        return app_log


Test patch:
diff --git a/tests/logging/__init__.py b/tests/logging/__init__.py
new file mode 100644
index 0000000..e69de29
diff --git a/tests/logging/test_logging_mixin.py b/tests/logging/test_logging_mixin.py
new file mode 100644
index 0000000..833562e
--- /dev/null
+++ b/tests/logging/test_logging_mixin.py
@@ -0,0 +1,19 @@
+import unittest
+from unittest import mock
+
+from remoteappmanager.logging.logging_mixin import LoggingMixin
+
+
+class Logged(LoggingMixin):
+    pass
+
+
+class TestLoggingMixin(unittest.TestCase):
+    def test_issue(self):
+        l = Logged()
+        with mock.patch("tornado.log.app_log.error") as mock_error:
+            ref = l.log.issue("hello")
+            self.assertIn("hello. Ref: "+str(ref), mock_error.call_args[0][0])
+            ref = l.log.issue("hello", Exception("Boom!"))
+            self.assertIn("hello : Boom!. Ref: "+str(ref),
+                          mock_error.call_args[0][0])