9287 history can log wrong exception information when operations fail
authorShawn Walker <srw@sun.com>
Fri, 17 Jul 2009 14:42:45 -0500
changeset 1235 7c34ba6e5e4f
parent 1234 d9885dff5d16
child 1236 15707d6de40b
9287 history can log wrong exception information when operations fail
src/modules/client/history.py
src/tests/api/t_history.py
src/tests/baseline.txt
--- a/src/modules/client/history.py	Fri Jul 17 14:35:26 2009 -0500
+++ b/src/modules/client/history.py	Fri Jul 17 14:42:45 2009 -0500
@@ -169,8 +169,11 @@
 Operation End State:
 %s
 Operation User: %s (%s)
+Operation Errors:
+%s
 """ % (self.name, self.result, self.start_time, self.end_time,
-    self.start_state, self.end_state, self.username, self.userid)
+    self.start_state, self.end_state, self.username, self.userid,
+    self.errors)
 
         # All "time" values should be in UTC, using ISO 8601 as the format.
         # Name of the operation performed (e.g. install, image-update, etc.).
@@ -286,6 +289,13 @@
                 # of just referencing self to avoid any of the special logic in
                 # place interfering with logic here.
                 if name == "operation_name":
+                        # Before a new operation starts, clear exception state
+                        # for the current one so that when this one ends, the
+                        # last operation's exception won't be recorded to this
+                        # one.  If the error hasn't been recorded by now, it
+                        # doesn't matter anyway, so should be safe to clear.
+                        sys.exc_clear()
+
                         # Mark the operation as having started and record
                         # other, relevant information.
                         op.start_time = misc.time_to_timestamp(None)
@@ -686,13 +696,24 @@
                 if self.operation_name:
                         out_stack = None
                         out_err = None
+                        use_current_stack = True
                         if isinstance(error, Exception):
-                                # Assume the exception being logged is the last
-                                # one that occurred and get its traceback.
-                                output = traceback.format_exc()
-                        else:
+                                # Attempt to get the exception's stack trace
+                                # from the stack.  If the exception on the stack
+                                # isn't the same object as the one being logged,
+                                # then we have to use the current stack (which
+                                # is somewhat less useful) instead of being able
+                                # to find the code location of the original
+                                # error.
+                                type, val, tb = sys.exc_info()
+                                if error == val:
+                                        output = traceback.format_exc()
+                                        use_current_stack = False
+
+                        if use_current_stack:
                                 # Assume the current stack is more useful if
-                                # the error doesn't inherit from Exception.
+                                # the error doesn't inherit from Exception or
+                                # we can't use the last exception's stack.
                                 out_stack = "".join(traceback.format_stack())
 
                                 if error:
@@ -702,13 +723,15 @@
                                         # it is not contained within the
                                         # output of format_exc().
                                         out_err = str(error)
-                                        if not out_err:
-                                                out_err = error.__class__.__name__
+                                        if not out_err or out_err == "None":
+                                                out_err = \
+                                                    error.__class__.__name__
 
                                 output = "".join([
                                     item for item in [out_stack, out_err]
                                     if item
                                 ])
+
                         self.operation_errors.append(output.strip())
 
         def create_snapshot(self):
--- a/src/tests/api/t_history.py	Fri Jul 17 14:35:26 2009 -0500
+++ b/src/tests/api/t_history.py	Fri Jul 17 14:42:45 2009 -0500
@@ -408,6 +408,42 @@
                 self.assertEqual(he.operation_end_state, "None")
                 self.assertEqual(he.operation_errors, [])
 
+        def test_12_bug_9287(self):
+                """Verify that the current exception stack won't be logged
+                unless it is for the same exception the operation ended
+                with."""
+
+                h = self.__h
+
+                # Test that an exception that occurs before an operation
+                # starts won't be recorded if it is not the same exception
+                # the operation ended with.
+
+                # Clear history completely.
+                h.purge()
+                shutil.rmtree(h.path)
+
+                # Populate the exception stack.
+                try:
+                        d = {}
+                        d['nosuchkey']
+                except KeyError:
+                        pass
+
+                h.log_operation_start("test-exceptions")
+                e = AssertionError()
+                h.log_operation_end(error=e)
+
+                for entry in sorted(os.listdir(h.path)):
+                        # Load the history entry.
+                        he = history.History(root_dir=h.root_dir,
+                            filename=entry)
+
+                        # Verify that the right exception was logged.
+                        for e in he.operation_errors:
+                                self.assertNotEqual(e.find("AssertionError"),
+                                    -1)
+
 if __name__ == "__main__":
         unittest.main()
 
--- a/src/tests/baseline.txt	Fri Jul 17 14:35:26 2009 -0500
+++ b/src/tests/baseline.txt	Fri Jul 17 14:42:45 2009 -0500
@@ -118,6 +118,7 @@
 api.t_history.py TestHistory.test_09_bug_5153|pass
 api.t_history.py TestHistory.test_10_snapshots|pass
 api.t_history.py TestHistory.test_11_bug_8072|pass
+api.t_history.py TestHistory.test_12_bug_9287|pass
 api.t_imageconfig.py TestImageConfig.test_0_read|pass
 api.t_imageconfig.py TestImageConfig.test_1_unicode|pass
 api.t_imageconfig.py TestImageConfig.test_2_missing_conffile|pass