[KVM-AUTOTEST PATCH 1/7] [RFC] Fix Unhandled* exceptions

[KVM-AUTOTEST PATCH 1/7] [RFC] Fix Unhandled* exceptions

[Michael Goldish]

In recent Python version, when exceptions are unpickled their __init__() method
is called again.  The parameters passed to __init__() upon unpickling are
*self.args.  Because the first execution of __init__() sets self.args to
something different from the parameters passed to __init__() (by passing
something to Exception.__init__()), upon unpickling __init__() is called with
unexpected parameters.

For example, if a NameError is raised in a test, UnhandledTestFail.__init__()
will call
Exception.__init__(self, "Unhandled NameError: ...").
Upon unpickling, UnhandledTestFail.__init__() will be called with "Unhandled
NameError: ..." which is a string.  It will then call
Exception.__init__(self, "Unhandled str: Unhandled NameError: ...")
because str is not an instance of TestFail.  The resulting exception's __str__()
method will return "Unhandled str: Unhandled NameError: ..." which isn't pretty.

To fix this, this patch makes the Unhandled* exceptions rely on __str__()
and attributes (self.unhandled_exception and self.traceback) instead of
__init__() and self.args.  An alternative solution could be to check whether
the parameter passed to __init__() is a string, and if so, pass it to the parent
exception's __init__() without modification.

Signed-off-by: Michael Goldish <mgoldish@redhat.com>
---
 client/bin/job.py          |    6 ++--
 client/common_lib/error.py |   51 ++++++++++++++++++++++++++++---------------
 2 files changed, 36 insertions(+), 21 deletions(-)

diff --git a/client/bin/job.py b/client/bin/job.py
index 3d552ce..f4306fc 100644
--- a/client/bin/job.py
+++ b/client/bin/job.py
@@ -1182,13 +1182,13 @@ def runjob(control, drop_caches, options):
         sys.exit(1)
 
     except error.JobError, instance:
-        logging.error("JOB ERROR: " + instance.args[0])
+        logging.error("JOB ERROR: " + str(instance))
         if myjob:
             command = None
             if len(instance.args) > 1:
                 command = instance.args[1]
-                myjob.record('ABORT', None, command, instance.args[0])
-            myjob.record('END ABORT', None, None, instance.args[0])
+                myjob.record('ABORT', None, command, str(instance))
+            myjob.record('END ABORT', None, None, str(instance))
             assert myjob._record_indent == 0
             myjob.complete(1)
         else:
diff --git a/client/common_lib/error.py b/client/common_lib/error.py
index 42dfe2b..71ba4e5 100644
--- a/client/common_lib/error.py
+++ b/client/common_lib/error.py
@@ -44,14 +44,19 @@ class JobError(AutotestError):
 class UnhandledJobError(JobError):
     """Indicates an unhandled error in a job."""
     def __init__(self, unhandled_exception):
-        if isinstance(unhandled_exception, JobError):
-            JobError.__init__(self, *unhandled_exception.args)
+        JobError.__init__(self, unhandled_exception)
+        self.unhandled_exception = unhandled_exception
+        self.traceback = traceback.format_exc()
+
+    def __str__(self):
+        if isinstance(self.unhandled_exception, JobError):
+            return JobError.__str__(self.unhandled_exception)
         else:
             msg = "Unhandled %s: %s"
-            msg %= (unhandled_exception.__class__.__name__,
-                    unhandled_exception)
-            msg += "\n" + traceback.format_exc()
-            JobError.__init__(self, msg)
+            msg %= (self.unhandled_exception.__class__.__name__,
+                    self.unhandled_exception)
+            msg += "\n" + self.traceback
+            return msg
 
 
 class TestBaseException(AutotestError):
@@ -85,27 +90,37 @@ class TestWarn(TestBaseException):
 class UnhandledTestError(TestError):
     """Indicates an unhandled error in a test."""
     def __init__(self, unhandled_exception):
-        if isinstance(unhandled_exception, TestError):
-            TestError.__init__(self, *unhandled_exception.args)
+        TestError.__init__(self, unhandled_exception)
+        self.unhandled_exception = unhandled_exception
+        self.traceback = traceback.format_exc()
+
+    def __str__(self):
+        if isinstance(self.unhandled_exception, TestError):
+            return TestError.__str__(self.unhandled_exception)
         else:
             msg = "Unhandled %s: %s"
-            msg %= (unhandled_exception.__class__.__name__,
-                    unhandled_exception)
-            msg += "\n" + traceback.format_exc()
-            TestError.__init__(self, msg)
+            msg %= (self.unhandled_exception.__class__.__name__,
+                    self.unhandled_exception)
+            msg += "\n" + self.traceback
+            return msg
 
 
 class UnhandledTestFail(TestFail):
     """Indicates an unhandled fail in a test."""
     def __init__(self, unhandled_exception):
-        if isinstance(unhandled_exception, TestFail):
-            TestFail.__init__(self, *unhandled_exception.args)
+        TestFail.__init__(self, unhandled_exception)
+        self.unhandled_exception = unhandled_exception
+        self.traceback = traceback.format_exc()
+
+    def __str__(self):
+        if isinstance(self.unhandled_exception, TestFail):
+            return TestFail.__str__(self.unhandled_exception)
         else:
             msg = "Unhandled %s: %s"
-            msg %= (unhandled_exception.__class__.__name__,
-                    unhandled_exception)
-            msg += "\n" + traceback.format_exc()
-            TestFail.__init__(self, msg)
+            msg %= (self.unhandled_exception.__class__.__name__,
+                    self.unhandled_exception)
+            msg += "\n" + self.traceback
+            return msg
 
 
 class CmdError(TestError):
-- 
1.7.3.4

[KVM-AUTOTEST PATCH 2/7] [RFC] CmdError: remove extra blank line between methods

[Michael Goldish]

For consistency with other exception classes, keep just a single blank line
between __init__() and __str__().

Signed-off-by: Michael Goldish <mgoldish@redhat.com>
---
 client/common_lib/error.py |    1 -
 1 files changed, 0 insertions(+), 1 deletions(-)

diff --git a/client/common_lib/error.py b/client/common_lib/error.py
index 71ba4e5..f1ddaea 100644
--- a/client/common_lib/error.py
+++ b/client/common_lib/error.py
@@ -133,7 +133,6 @@ class CmdError(TestError):
         self.result_obj = result_obj
         self.additional_text = additional_text
 
-
     def __str__(self):
         if self.result_obj.exit_status is None:
             msg = "Command <%s> failed and is not responding to signals"
-- 
1.7.3.4

[KVM-AUTOTEST PATCH 3/7] [RFC] Introduce exception context strings

[Michael Goldish]

In complex tests (KVM) an exception string is often not informative enough and
the traceback and source code have to be examined in order to figure out what
caused the exception.  Context strings are a way for tests to provide
information about what they're doing, so that when an exception is raised, this
information will be embedded in the exception string.  The result is a concise
yet highly informative exception string, which should make it very easy to
figure out where/when the exception was raised.

A typical example for a test where this may be useful is KVM's reboot test.
Some exceptions can be raised either before or after the VM is rebooted (e.g.
logging into the guest can fail) and whether they are raised before or after
is critical to the understanding of the failure.  Normally the traceback would
have to be examined, but the proposed method makes it easy to know where the
exception is raised without doing so.  To achieve this, the reboot test should
place calls to error.context() as follows:

error.context("before reboot")
<carry out pre-reboot actions>
error.context("sending reboot command")
<send the reboot command>
error.context("after reboot")
<carry out post-reboot actions>

If login fails in the pre-reboot section, the resulting exception string can
can have something like "context: before reboot" embedded in it.  (The actual
embedding is done in the next patch in the series.)

Signed-off-by: Michael Goldish <mgoldish@redhat.com>
---
 client/common_lib/error.py |   82 ++++++++++++++++++++++++++++++++++++++++++-
 1 files changed, 80 insertions(+), 2 deletions(-)

diff --git a/client/common_lib/error.py b/client/common_lib/error.py
index f1ddaea..394f555 100644
--- a/client/common_lib/error.py
+++ b/client/common_lib/error.py
@@ -2,13 +2,13 @@
 Internal global error types
 """
 
-import sys, traceback
+import sys, traceback, threading, logging
 from traceback import format_exception
 
 # Add names you want to be imported by 'from errors import *' to this list.
 # This must be list not a tuple as we modify it to include all of our
 # the Exception classes we define below at the end of this file.
-__all__ = ['format_error']
+__all__ = ['format_error', 'context', 'get_context']
 
 
 def format_error():
@@ -21,6 +21,84 @@ def format_error():
     return ''.join(trace)
 
 
+# Exception context information:
+# ------------------------------
+# Every function can have some context string associated with it.
+# The context string can be changed by calling context(str) and cleared by
+# calling context() with no parameters.
+# get_context() joins the current context strings of all functions in the
+# provided traceback.  The result is a brief description of what the test was
+# doing in the provided traceback (which should be the traceback of a caught
+# exception).
+#
+# For example: assume a() calls b() and b() calls c().
+#
+# def a():
+#     error.context("hello")
+#     b()
+#     error.context("world")
+#     get_context() ----> 'world'
+#
+# def b():
+#     error.context("foo")
+#     c()
+#
+# def c():
+#     error.context("bar")
+#     get_context() ----> 'hello --> foo --> bar'
+
+context_data = threading.local()
+context_data.contexts = {}
+
+
+def context(c=None, log=logging.info):
+    """
+    Set the context for the currently executing function and log it as an INFO
+    message by default.
+
+    @param c: A string or None.  If c is None or an empty string, the context
+            for the current function is cleared.
+    @param log: A logging function to pass the string to.  If None, no function
+            will be called.
+    """
+    stack = traceback.extract_stack()
+    try:
+        key_parts = ["%s:%s:%s:" % (filename, func, lineno)
+                     for filename, lineno, func, text in stack[:-2]]
+        filename, lineno, func, text = stack[-2]
+        key_parts.append("%s:%s" % (filename, func))
+        key = "".join(key_parts)
+        if c:
+            context_data.contexts[key] = c
+            if log:
+                log("Context: %s" % c)
+        elif key in context_data.contexts:
+            del context_data.contexts[key]
+    finally:
+        # Prevent circular references
+        del stack
+
+
+def get_context(tb):
+    """
+    Construct a context string from the given traceback.
+
+    @param tb: A traceback object (usually sys.exc_info()[2]).
+    """
+    l = []
+    key = ""
+    for filename, lineno, func, text in traceback.extract_tb(tb):
+        key += "%s:%s" % (filename, func)
+        # An exception's traceback is relative to the function that handles it,
+        # so instead of an exact match, we expect the traceback entries to be
+        # suffixes of the stack entries recorded using extract_stack().
+        for key_ in context_data.contexts:
+            if key_.endswith(key):
+                l.append(context_data.contexts[key_])
+        key += ":%s:" % lineno
+    return " --> ".join(l)
+
+
 class JobContinue(SystemExit):
     """Allow us to bail out requesting continuance."""
     pass
-- 
1.7.3.4

[KVM-AUTOTEST PATCH 4/7] [RFC] Embed context information in exception strings

[Michael Goldish]

Exceptions look for a .context attribute and embed it in the string returned by
__str__().  If the attribute isn't set (or if it's an empty strgin) nothing is
embedded.

Signed-off-by: Michael Goldish <mgoldish@redhat.com>
---
 client/common_lib/error.py |   13 ++++++++++++-
 1 files changed, 12 insertions(+), 1 deletions(-)

diff --git a/client/common_lib/error.py b/client/common_lib/error.py
index 394f555..ed7132e 100644
--- a/client/common_lib/error.py
+++ b/client/common_lib/error.py
@@ -111,7 +111,14 @@ class JobComplete(SystemExit):
 
 class AutotestError(Exception):
     """The parent of all errors deliberatly thrown within the client code."""
-    pass
+    def context_str(self):
+        if hasattr(self, "context") and self.context:
+            return "    [context: %s]" % self.context
+        else:
+            return ""
+
+    def __str__(self):
+        return Exception.__str__(self) + self.context_str()
 
 
 class JobError(AutotestError):
@@ -133,6 +140,7 @@ class UnhandledJobError(JobError):
             msg = "Unhandled %s: %s"
             msg %= (self.unhandled_exception.__class__.__name__,
                     self.unhandled_exception)
+            msg += self.context_str()
             msg += "\n" + self.traceback
             return msg
 
@@ -179,6 +187,7 @@ class UnhandledTestError(TestError):
             msg = "Unhandled %s: %s"
             msg %= (self.unhandled_exception.__class__.__name__,
                     self.unhandled_exception)
+            msg += self.context_str()
             msg += "\n" + self.traceback
             return msg
 
@@ -197,6 +206,7 @@ class UnhandledTestFail(TestFail):
             msg = "Unhandled %s: %s"
             msg %= (self.unhandled_exception.__class__.__name__,
                     self.unhandled_exception)
+            msg += self.context_str()
             msg += "\n" + self.traceback
             return msg
 
@@ -221,6 +231,7 @@ class CmdError(TestError):
 
         if self.additional_text:
             msg += ", " + self.additional_text
+        msg += self.context_str()
         msg += '\n' + repr(self.result_obj)
         return msg
 
-- 
1.7.3.4

[KVM-AUTOTEST PATCH 5/7] [RFC] Set the .context attribute for exceptions in _call_test_function()

[Michael Goldish]

Before passing exceptions on up, inject context information into them which can
later be used by __str__().

Signed-off-by: Michael Goldish <mgoldish@redhat.com>
---
 client/common_lib/test.py |   16 ++++++++++------
 1 files changed, 10 insertions(+), 6 deletions(-)

diff --git a/client/common_lib/test.py b/client/common_lib/test.py
index 2561242..9521326 100644
--- a/client/common_lib/test.py
+++ b/client/common_lib/test.py
@@ -596,13 +596,17 @@ def _call_test_function(func, *args, **dargs):
     inside test code are considered test failures."""
     try:
         return func(*args, **dargs)
-    except error.AutotestError:
-        # Pass already-categorized errors on up as is.
-        raise
+    except error.AutotestError, e:
+        # Inject context info and pass already-categorized errors on up.
+        e.context = error.get_context(sys.exc_info()[2])
+        raise sys.exc_info()[0], e, sys.exc_info()[2]
     except Exception, e:
-        # Other exceptions must be treated as a FAIL when
-        # raised during the test functions
-        raise error.UnhandledTestFail(e)
+        # Other exceptions are treated as a FAIL when raised during the test
+        # functions.  Convert them to UnhandledTestFail, inject context info
+        # and pass them on up.
+        e = error.UnhandledTestFail(e)
+        e.context = error.get_context(sys.exc_info()[2])
+        raise e
 
 
 def runtest(job, url, tag, args, dargs,
-- 
1.7.3.4

[KVM-AUTOTEST PATCH 6/7] [RFC] KVM test: use error.context() in migration_with_file_transfer

[Michael Goldish]

This is an example of a case where context information is useful.

Signed-off-by: Michael Goldish <mgoldish@redhat.com>
---
 .../kvm/tests/migration_with_file_transfer.py      |    8 +++++---
 1 files changed, 5 insertions(+), 3 deletions(-)

diff --git a/client/tests/kvm/tests/migration_with_file_transfer.py b/client/tests/kvm/tests/migration_with_file_transfer.py
index 27c1fe1..d0159c5 100644
--- a/client/tests/kvm/tests/migration_with_file_transfer.py
+++ b/client/tests/kvm/tests/migration_with_file_transfer.py
@@ -47,24 +47,26 @@ def run_migration_with_file_transfer(test, params, env):
             finally:
                 bg.join()
 
-        logging.info("Transferring file from host to guest")
+        error.context("transferring file to guest while migrating")
         bg = kvm_utils.Thread(vm.copy_files_to,
                               (host_path, guest_path, 0, transfer_timeout))
         run_and_migrate(bg)
 
-        logging.info("Transferring file back from guest to host")
+        error.context("transferring file back to host while migrating")
         bg = kvm_utils.Thread(vm.copy_files_from,
                               (guest_path, host_path_returned, 0,
                                transfer_timeout))
         run_and_migrate(bg)
 
-        # Make sure the returned file is indentical to the original one
+        # Make sure the returned file is identical to the original one
+        error.context("comparing hashes")
         orig_hash = client_utils.hash_file(host_path)
         returned_hash = client_utils.hash_file(host_path_returned)
         if orig_hash != returned_hash:
             raise error.TestFail("Returned file hash (%s) differs from "
                                  "original one (%s)" % (returned_hash,
                                                         orig_hash))
+        error.context("cleanup")
     finally:
         session.close()
         if os.path.isfile(host_path):
-- 
1.7.3.4

[KVM-AUTOTEST PATCH 7/7] [RFC] KVM test: use error.context() in kvm_preprocessing.py

[Michael Goldish]

Signed-off-by: Michael Goldish <mgoldish@redhat.com>
---
 client/tests/kvm/kvm_preprocessing.py |    9 +++++++--
 1 files changed, 7 insertions(+), 2 deletions(-)

diff --git a/client/tests/kvm/kvm_preprocessing.py b/client/tests/kvm/kvm_preprocessing.py
index 5ce0a3b..b7f3154 100644
--- a/client/tests/kvm/kvm_preprocessing.py
+++ b/client/tests/kvm/kvm_preprocessing.py
@@ -49,7 +49,8 @@ def preprocess_vm(test, params, env, name):
     @param env: The environment (a dict-like object).
     @param name: The name of the VM object.
     """
-    logging.debug("Preprocessing VM '%s'..." % name)
+    error.context("preprocessing '%s'" % name)
+
     vm = env.get_vm(name)
     if vm:
         logging.debug("VM object found in environment")
@@ -114,7 +115,7 @@ def postprocess_vm(test, params, env, name):
     @param env: The environment (a dict-like object).
     @param name: The name of the VM object.
     """
-    logging.debug("Postprocessing VM '%s'..." % name)
+    error.context("postprocessing '%s'" % name)
     vm = env.get_vm(name)
     if vm:
         logging.debug("VM object found in environment")
@@ -196,6 +197,8 @@ def preprocess(test, params, env):
     @param params: A dict containing all VM and image parameters.
     @param env: The environment (a dict-like object).
     """
+    error.context("preprocessing")
+
     # Start tcpdump if it isn't already running
     if "address_cache" not in env:
         env["address_cache"] = {}
@@ -282,6 +285,8 @@ def postprocess(test, params, env):
     @param params: Dict containing all VM and image parameters.
     @param env: The environment (a dict-like object).
     """
+    error.context("postprocessing")
+
     # Postprocess all VMs and images
     process(test, params, env, postprocess_image, postprocess_vm)
 
-- 
1.7.3.4

Re: [KVM-AUTOTEST PATCH 3/7] [RFC] Introduce exception context strings

[Eduardo Habkost]

On Mon, Jan 03, 2011 at 08:34:07PM +0200, Michael Goldish wrote:
> +# Exception context information:
> +# ------------------------------
> +# Every function can have some context string associated with it.
> +# The context string can be changed by calling context(str) and cleared by
> +# calling context() with no parameters.
> +# get_context() joins the current context strings of all functions in the
> +# provided traceback.  The result is a brief description of what the test was
> +# doing in the provided traceback (which should be the traceback of a caught
> +# exception).

I am sure people will eventually forget to call context() to clear
previous context calls, and people won't notice until an actual error is
raised on another section.

What about a decorator like:

@context("hello")
def a()
    ...

That would set/clear the context automatically when the function is
called/returns?


> +#
> +# For example: assume a() calls b() and b() calls c().
> +#
> +# def a():
> +#     error.context("hello")
> +#     b()
> +#     error.context("world")
> +#     get_context() ----> 'world'
> +#
> +# def b():
> +#     error.context("foo")
> +#     c()
> +#
> +# def c():
> +#     error.context("bar")
> +#     get_context() ----> 'hello --> foo --> bar'

Above sample code is a good candidate to be in a doctest string or unit
test, isn't it?

-- 
Eduardo

Re: [Autotest] [KVM-AUTOTEST PATCH 3/7] [RFC] Introduce exception context strings

[Eduardo Habkost]

On Mon, Jan 03, 2011 at 05:26:20PM -0200, Eduardo Habkost wrote:
> On Mon, Jan 03, 2011 at 08:34:07PM +0200, Michael Goldish wrote:
> > +# Exception context information:
> > +# ------------------------------
> > +# Every function can have some context string associated with it.
> > +# The context string can be changed by calling context(str) and cleared by
> > +# calling context() with no parameters.
> > +# get_context() joins the current context strings of all functions in the
> > +# provided traceback.  The result is a brief description of what the test was
> > +# doing in the provided traceback (which should be the traceback of a caught
> > +# exception).
> 
> I am sure people will eventually forget to call context() to clear
> previous context calls, and people won't notice until an actual error is
> raised on another section.
> 

I am looking further at the code, now. Does the stack and traceback
tricks mean that the effects of a context("foo") call will be lost as
soon as we return from a function?

I would say this is a bad idea for a conventional API, but I think it
may be acceptable considering that the purpose of those tricks is to
make function tracebacks easier to understand.

-- 
Eduardo

Re: [KVM-AUTOTEST PATCH 3/7] [RFC] Introduce exception context strings

[Michael Goldish]

On 01/03/2011 09:26 PM, Eduardo Habkost wrote:
> On Mon, Jan 03, 2011 at 08:34:07PM +0200, Michael Goldish wrote:
>> +# Exception context information:
>> +# ------------------------------
>> +# Every function can have some context string associated with it.
>> +# The context string can be changed by calling context(str) and cleared by
>> +# calling context() with no parameters.
>> +# get_context() joins the current context strings of all functions in the
>> +# provided traceback.  The result is a brief description of what the test was
>> +# doing in the provided traceback (which should be the traceback of a caught
>> +# exception).
> 
> I am sure people will eventually forget to call context() to clear
> previous context calls, and people won't notice until an actual error is
> raised on another section.
> 
> What about a decorator like:
> 
> @context("hello")
> def a()
>     ...
> 
> That would set/clear the context automatically when the function is
> called/returns?

- In most cases it isn't necessary. The context dict maps whole stack
traces to context strings, which means that if a function is called
twice from different places in the code, it won't have the same context
string.  The only problematic case is functions that are called in loops
and declare context strings.  I suppose those should be rare, and all
they need to do to prevent the problem is call error.context() at the top.
- A function can (and should) change its context string at runtime (for
example: before reboot, after reboot).  If each function could only
declare a single context, we could just use the function's name and we
wouldn't need a context.

>> +#
>> +# For example: assume a() calls b() and b() calls c().
>> +#
>> +# def a():
>> +#     error.context("hello")
>> +#     b()
>> +#     error.context("world")
>> +#     get_context() ----> 'world'
>> +#
>> +# def b():
>> +#     error.context("foo")
>> +#     c()
>> +#
>> +# def c():
>> +#     error.context("bar")
>> +#     get_context() ----> 'hello --> foo --> bar'
> 
> Above sample code is a good candidate to be in a doctest string or unit
> test, isn't it?
> 

Probably, but I've never used those before so I'll have to find out how
it's done.

Re: [KVM-AUTOTEST PATCH 3/7] [RFC] Introduce exception context strings

[Eduardo Habkost]

On Mon, Jan 03, 2011 at 09:48:02PM +0200, Michael Goldish wrote:
> On 01/03/2011 09:26 PM, Eduardo Habkost wrote:
> > On Mon, Jan 03, 2011 at 08:34:07PM +0200, Michael Goldish wrote:
> >> +# Exception context information:
> >> +# ------------------------------
> >> +# Every function can have some context string associated with it.
> >> +# The context string can be changed by calling context(str) and cleared by
> >> +# calling context() with no parameters.
> >> +# get_context() joins the current context strings of all functions in the
> >> +# provided traceback.  The result is a brief description of what the test was
> >> +# doing in the provided traceback (which should be the traceback of a caught
> >> +# exception).
> > 
> > I am sure people will eventually forget to call context() to clear
> > previous context calls, and people won't notice until an actual error is
> > raised on another section.
> > 
> > What about a decorator like:
> > 
> > @context("hello")
> > def a()
> >     ...
> > 
> > That would set/clear the context automatically when the function is
> > called/returns?
> 
> - In most cases it isn't necessary. The context dict maps whole stack
> traces to context strings, which means that if a function is called
> twice from different places in the code, it won't have the same context
> string.  The only problematic case is functions that are called in loops
> and declare context strings.  I suppose those should be rare, and all
> they need to do to prevent the problem is call error.context() at the top.
> - A function can (and should) change its context string at runtime (for
> example: before reboot, after reboot).  If each function could only
> declare a single context, we could just use the function's name and we
> wouldn't need a context.

OK, I am convinced about the general features of the API (one context
per function call).

Now, about the internal implementation: what about something to avoid
using the stack trace tricks on context()? Basically what you need is
something that adds a new "context entry" when a function is called and
clear it once the function returns.

What about a decorator tyat indicates "this function will push/pop a context
when it is called/returns"? It looks much simpler than doing the tricks
involving the stack on every context() call.


e.g. I would find something like the following much easier to understand:

CTX = threading.local()
CTX.contexts = []

def context(s):
    """Change current context"""
    CTX.contexts[-1] = s

def new_context(s):
    """Push new context in the stack"""
    CTX.contexts.append(s)

def clear_context():
    """Remove current context from the stack"""
    CTX.contexts.pop()

def get_context():
    return " --> ".join(CTX.contexts)

def context_aware(fn):
    # quick solution. using decorator util functions to keep function metadata would be better
    def docall(*args, **kwargs):
        new_context("[%s function begin]" % (fn.__name__))
        try:
            return fn(*args, **kwargs)
        finally:
            clear_context()
    return docall


### sample usage:
@context_aware
def a():
    context("hello")
    b()
    context("world")
    print 'b:',get_context() # ----> 'world'

@context_aware
def b():
    context("foo")
    c()

@context_aware
def c():
    context("bar")
    print 'c:',get_context() # ----> 'hello --> foo --> bar'

-- 
Eduardo

Re: [KVM-AUTOTEST PATCH 3/7] [RFC] Introduce exception context strings

[Eduardo Habkost]

On Mon, Jan 03, 2011 at 08:34:07PM +0200, Michael Goldish wrote:
> +
> +context_data = threading.local()
> +context_data.contexts = {}

Won't this create a single dictionary, only for one single thread,
leaving all other threads with 'context_data.contexts' undefined?

-- 
Eduardo

Re: [Autotest] [KVM-AUTOTEST PATCH 3/7] [RFC] Introduce exception context strings

[Michael Goldish]

On 01/03/2011 10:26 PM, Eduardo Habkost wrote:
> On Mon, Jan 03, 2011 at 08:34:07PM +0200, Michael Goldish wrote:
>> +
>> +context_data = threading.local()
>> +context_data.contexts = {}
> 
> Won't this create a single dictionary, only for one single thread,
> leaving all other threads with 'context_data.contexts' undefined?

Probably. I'll fix that.

Re: [KVM-AUTOTEST PATCH 3/7] [RFC] Introduce exception context strings

[Michael Goldish]

On 01/03/2011 10:16 PM, Eduardo Habkost wrote:
> On Mon, Jan 03, 2011 at 09:48:02PM +0200, Michael Goldish wrote:
>> On 01/03/2011 09:26 PM, Eduardo Habkost wrote:
>>> On Mon, Jan 03, 2011 at 08:34:07PM +0200, Michael Goldish wrote:
>>>> +# Exception context information:
>>>> +# ------------------------------
>>>> +# Every function can have some context string associated with it.
>>>> +# The context string can be changed by calling context(str) and cleared by
>>>> +# calling context() with no parameters.
>>>> +# get_context() joins the current context strings of all functions in the
>>>> +# provided traceback.  The result is a brief description of what the test was
>>>> +# doing in the provided traceback (which should be the traceback of a caught
>>>> +# exception).
>>>
>>> I am sure people will eventually forget to call context() to clear
>>> previous context calls, and people won't notice until an actual error is
>>> raised on another section.
>>>
>>> What about a decorator like:
>>>
>>> @context("hello")
>>> def a()
>>>     ...
>>>
>>> That would set/clear the context automatically when the function is
>>> called/returns?
>>
>> - In most cases it isn't necessary. The context dict maps whole stack
>> traces to context strings, which means that if a function is called
>> twice from different places in the code, it won't have the same context
>> string.  The only problematic case is functions that are called in loops
>> and declare context strings.  I suppose those should be rare, and all
>> they need to do to prevent the problem is call error.context() at the top.
>> - A function can (and should) change its context string at runtime (for
>> example: before reboot, after reboot).  If each function could only
>> declare a single context, we could just use the function's name and we
>> wouldn't need a context.
> 
> OK, I am convinced about the general features of the API (one context
> per function call).
> 
> Now, about the internal implementation: what about something to avoid
> using the stack trace tricks on context()? Basically what you need is
> something that adds a new "context entry" when a function is called and
> clear it once the function returns.
> 
> What about a decorator tyat indicates "this function will push/pop a context
> when it is called/returns"? It looks much simpler than doing the tricks
> involving the stack on every context() call.
> 
> 
> e.g. I would find something like the following much easier to understand:
> 
> CTX = threading.local()
> CTX.contexts = []
> 
> def context(s):
>     """Change current context"""
>     CTX.contexts[-1] = s
> 
> def new_context(s):
>     """Push new context in the stack"""
>     CTX.contexts.append(s)
> 
> def clear_context():
>     """Remove current context from the stack"""
>     CTX.contexts.pop()
> 
> def get_context():
>     return " --> ".join(CTX.contexts)
> 
> def context_aware(fn):
>     # quick solution. using decorator util functions to keep function metadata would be better
>     def docall(*args, **kwargs):
>         new_context("[%s function begin]" % (fn.__name__))
>         try:
>             return fn(*args, **kwargs)
>         finally:
>             clear_context()
>     return docall
> 
> 
> ### sample usage:
> @context_aware
> def a():
>     context("hello")
>     b()
>     context("world")
>     print 'b:',get_context() # ----> 'world'
> 
> @context_aware
> def b():
>     context("foo")
>     c()
> 
> @context_aware
> def c():
>     context("bar")
>     print 'c:',get_context() # ----> 'hello --> foo --> bar'
> 

If I understand your suggestion correctly, then:

- The purpose of contexts is to add information to exceptions.  If an
exception is raised and you call clear_context() in a finally clause,
you remove the context of the current function.  If the function itself
calls get_context() it'll see the current context, but as soon as an
exception is raised the context disappears all the way up to the point
where the exception is caught.

- A possible solution would be not to use finally and only call
clear_context() if the function terminates successfully.  Then if a
function raises an exception, the context remains for some handler to
catch and print.  However, if we catch the exception sometime later and
decide not to fail the test (for example: login failed and we don't
care) then we have to pop some context items, or the context stack will
be corrupted.

- Additionally, if some function raises an exception and we perform some
cleanup in a finally clause, and during that cleanup we call another
function that calls context(), then our context stack will be modified
by the other function, and the context handler (which calls
get_context()) will not see the original context but rather a modified one.

Let me know if I misunderstood something.

Thanks,
Michael

Re: [KVM-AUTOTEST PATCH 3/7] [RFC] Introduce exception context strings

[Eduardo Habkost]

On Mon, Jan 03, 2011 at 11:07:53PM +0200, Michael Goldish wrote:
> 
> If I understand your suggestion correctly, then:
> 
> - The purpose of contexts is to add information to exceptions.  If an
> exception is raised and you call clear_context() in a finally clause,
> you remove the context of the current function.  If the function itself
> calls get_context() it'll see the current context, but as soon as an
> exception is raised the context disappears all the way up to the point
> where the exception is caught.

I need to add the code to save the context stack when an exception is
raised (I focused on the code to save the context information and forgot
about the initial purpose  :).

> 
> - A possible solution would be not to use finally and only call
> clear_context() if the function terminates successfully.  Then if a
> function raises an exception, the context remains for some handler to
> catch and print.  However, if we catch the exception sometime later and
> decide not to fail the test (for example: login failed and we don't
> care) then we have to pop some context items, or the context stack will
> be corrupted.

When an exception is raised, you don't need to keep the context stack
untouched, you can pop it anyway. You just need to save a copy of the
current stack in case the exception is never handled.

> 
> - Additionally, if some function raises an exception and we perform some
> cleanup in a finally clause, and during that cleanup we call another
> function that calls context(), then our context stack will be modified
> by the other function, and the context handler (which calls
> get_context()) will not see the original context but rather a modified one.

We can just save the context when an exception is raised. If upper in
the stack some other @context_aware function gets the same exception, we
don't need to save it again. If the exception is ignored, we can just
leave the saved context there (it would be overwritten if a new
exception is raised later, anyway).

I will try to make it work and send a new version. I believe we won't
need stack trace tricks to make that work.

-- 
Eduardo

Re: [Autotest] [KVM-AUTOTEST PATCH 3/7] [RFC] Introduce exception context strings

[Eduardo Habkost]

On Mon, Jan 03, 2011 at 07:22:17PM -0200, Eduardo Habkost wrote:
> On Mon, Jan 03, 2011 at 11:07:53PM +0200, Michael Goldish wrote:
> > 
> > If I understand your suggestion correctly, then:
> > 
> > - The purpose of contexts is to add information to exceptions.  If an
> > exception is raised and you call clear_context() in a finally clause,
> > you remove the context of the current function.  If the function itself
> > calls get_context() it'll see the current context, but as soon as an
> > exception is raised the context disappears all the way up to the point
> > where the exception is caught.
> 
> I need to add the code to save the context stack when an exception is
> raised (I focused on the code to save the context information and forgot
> about the initial purpose  :).
> 
> > 
> > - A possible solution would be not to use finally and only call
> > clear_context() if the function terminates successfully.  Then if a
> > function raises an exception, the context remains for some handler to
> > catch and print.  However, if we catch the exception sometime later and
> > decide not to fail the test (for example: login failed and we don't
> > care) then we have to pop some context items, or the context stack will
> > be corrupted.
> 
> When an exception is raised, you don't need to keep the context stack
> untouched, you can pop it anyway. You just need to save a copy of the
> current stack in case the exception is never handled.
> 
> > 
> > - Additionally, if some function raises an exception and we perform some
> > cleanup in a finally clause, and during that cleanup we call another
> > function that calls context(), then our context stack will be modified
> > by the other function, and the context handler (which calls
> > get_context()) will not see the original context but rather a modified one.
> 
> We can just save the context when an exception is raised. If upper in
> the stack some other @context_aware function gets the same exception, we
> don't need to save it again. If the exception is ignored, we can just
> leave the saved context there (it would be overwritten if a new
> exception is raised later, anyway).
> 
> I will try to make it work and send a new version. I believe we won't
> need stack trace tricks to make that work.

What about the following code?

I used 'cur_exception is last_exception' to check if an upper function
is handling the same Exception that a lower function already saved. We
could store/compare the traceback object from sys.exc_info() if we
wanted to keep track of a traceback->context mapping instead of
exception->context mapping, but I think the traceback information is
more likely to be lost in a "except ...,e: raise e" construct somewhere,
than the Exception object identity.

If you want to be extra careful, you can keep an index of contexts for
each exception ever seen, and clear it in _call_test_function() code,
instead of keeping only the last exception. But I think we can keep it
simple and just store info for the last exception.

----------------------------------
import threading, decorator

CTX = threading.local()

def _ctx(f, default):
    """Get a field from CTX and set a default if not set"""
    if not hasattr(CTX, f):
        setattr(CTX, f, default)
    return getattr(CTX, f)

def _context_str(ctx):
    """Return string representation of a context"""
    return " --> ".join(ctx)


def context(s):
    """Change current context"""
    CTX.context[-1] = s

def new_context(s):
    """Push new context in the stack"""
    _ctx('context', []).append(s)

def clear_context():
    """Remove current context from the stack"""
    CTX.context.pop()

def get_context():
    """Get a description of the current context"""
    return _context_str(_ctx('context', []))

def _last_exception():
    return _ctx('last_exception', None)

def _context_for_exception(e):
    """Get information for the context where an exception was raised

    It requires getting the exception as argument for safety, to make sure
    information for the right exception is returned.
    """
    if e is _last_exception():
        return CTX.last_exception_context

def context_for_exception(e):
    return _context_str(_context_for_exception(e))

def _context_aware(fn, *args, **kwargs):
    new_context("[%s function begin]" % (fn.__name__))
    try:
        try:
            return fn(*args, **kwargs)
        except Exception,e:
            if e is not _last_exception():
                CTX.last_exception = e
                CTX.last_exception_context = CTX.context[:] # make a copy
            raise
    finally:
        clear_context()

context_aware = decorator.decorator(_context_aware)


## test code:
#############

import unittest
class TestContext(unittest.TestCase):
    def testSimpleCtx(self):
        @context_aware
        def a():
            context("hello")
            b()
            context("world")
            self.assertEquals(get_context(), 'world')

        @context_aware
        def b():
            context("foo")
            c()

        @context_aware
        def c():
            context("bar")
            self.assertEquals(get_context(), 'hello --> foo --> bar')

        a() # test it
        self.assertEquals(get_context(), '') # no context after everything returned


    def testException(self):
        @context_aware
        def try_something():
            context("trying something")
            raise Exception("something failed")

        @context_aware
        def do_something():
            context("do this")
            context("do that")
            context("try something")
            try_something()
            context("do something else")

        @context_aware
        def main():
            context("main code")
            context("do something")
            do_something()

        def test_exception():
            try:
                main()
            except Exception,e:
                ctx = context_for_exception(e)
                self.assertEquals(ctx, 'do something --> try something --> trying something')
                self.assertEquals(str(e), "something failed")
            else:
                self.fail('exception not raised')

        test_exception()
        self.assertEquals(get_context(), '') # no context after everything returned

    def testDroppedException(self):
        @context_aware
        def try_something():
            context("trying something")
            raise Exception("something failed")

        @context_aware
        def do_something():
            context("do this")
            context("do that")
            context("try something")
            try:
                try_something()
            except Exception,e:
                # function may do something here after handling the exception
                pass
            context("do something else")

        @context_aware
        def main():
            context("main code")
            context("do something")
            do_something()
            context("after do something")
            raise Exception("another failure")

        def test_exception():
            try:
                main()
            except Exception,e:
                ctx = context_for_exception(e)
                self.assertEquals(ctx, 'after do something')
                self.assertEquals(str(e), "another failure")
            else:
                self.fail('exception not raised')

        test_exception()
        self.assertEquals(get_context(), '') # no context after everything returned

-- 
Eduardo

Re: [Autotest] [KVM-AUTOTEST PATCH 3/7] [RFC] Introduce exception context strings

[Michael Goldish]

On 01/04/2011 12:06 AM, Eduardo Habkost wrote:
> On Mon, Jan 03, 2011 at 07:22:17PM -0200, Eduardo Habkost wrote:
>> On Mon, Jan 03, 2011 at 11:07:53PM +0200, Michael Goldish wrote:
>>>
>>> If I understand your suggestion correctly, then:
>>>
>>> - The purpose of contexts is to add information to exceptions.  If an
>>> exception is raised and you call clear_context() in a finally clause,
>>> you remove the context of the current function.  If the function itself
>>> calls get_context() it'll see the current context, but as soon as an
>>> exception is raised the context disappears all the way up to the point
>>> where the exception is caught.
>>
>> I need to add the code to save the context stack when an exception is
>> raised (I focused on the code to save the context information and forgot
>> about the initial purpose  :).
>>
>>>
>>> - A possible solution would be not to use finally and only call
>>> clear_context() if the function terminates successfully.  Then if a
>>> function raises an exception, the context remains for some handler to
>>> catch and print.  However, if we catch the exception sometime later and
>>> decide not to fail the test (for example: login failed and we don't
>>> care) then we have to pop some context items, or the context stack will
>>> be corrupted.
>>
>> When an exception is raised, you don't need to keep the context stack
>> untouched, you can pop it anyway. You just need to save a copy of the
>> current stack in case the exception is never handled.
>>
>>>
>>> - Additionally, if some function raises an exception and we perform some
>>> cleanup in a finally clause, and during that cleanup we call another
>>> function that calls context(), then our context stack will be modified
>>> by the other function, and the context handler (which calls
>>> get_context()) will not see the original context but rather a modified one.
>>
>> We can just save the context when an exception is raised. If upper in
>> the stack some other @context_aware function gets the same exception, we
>> don't need to save it again. If the exception is ignored, we can just
>> leave the saved context there (it would be overwritten if a new
>> exception is raised later, anyway).
>>
>> I will try to make it work and send a new version. I believe we won't
>> need stack trace tricks to make that work.
> 
> What about the following code?
> 
> I used 'cur_exception is last_exception' to check if an upper function
> is handling the same Exception that a lower function already saved. We
> could store/compare the traceback object from sys.exc_info() if we
> wanted to keep track of a traceback->context mapping instead of
> exception->context mapping, but I think the traceback information is
> more likely to be lost in a "except ...,e: raise e" construct somewhere,
> than the Exception object identity.
> 
> If you want to be extra careful, you can keep an index of contexts for
> each exception ever seen, and clear it in _call_test_function() code,
> instead of keeping only the last exception. But I think we can keep it
> simple and just store info for the last exception.

I think that's risky:

try:
    vm.create()   # context aware, raises an exception
except:
    try:
        vm.destroy()  # context aware, raises an exception
    except:
        pass
    raise

The exception raised in VM.destroy() will override last_exception, and
then whoever calls context_for_exception() will get the wrong context.

But I think this will work and it looks pretty clean:

def _context_aware(fn, *args, **kwargs):
    new_context("")
    try:
        try:
            return fn(*args, **kwargs)
        except Exception, e:
            if not hasattr(e, "context"):
                e.context = get_context()
            raise sys.exc_info()[0], e, sys.exc_info()[2]
    finally:
        clear_context()

This way we don't need to keep track of the last exception, and we even
take care of the injection of .context here (instead of in test.py), so
we don't need context_for_exception() at all.
What do you think?
If this makes sense, I'd like to rewrite my patch using this decorator,
unless you feel like doing so yourself.

Thanks,
Michael

> ----------------------------------
> import threading, decorator
> 
> CTX = threading.local()
> 
> def _ctx(f, default):
>     """Get a field from CTX and set a default if not set"""
>     if not hasattr(CTX, f):
>         setattr(CTX, f, default)
>     return getattr(CTX, f)
> 
> def _context_str(ctx):
>     """Return string representation of a context"""
>     return " --> ".join(ctx)
> 
> 
> def context(s):
>     """Change current context"""
>     CTX.context[-1] = s
> 
> def new_context(s):
>     """Push new context in the stack"""
>     _ctx('context', []).append(s)
> 
> def clear_context():
>     """Remove current context from the stack"""
>     CTX.context.pop()
> 
> def get_context():
>     """Get a description of the current context"""
>     return _context_str(_ctx('context', []))
> 
> def _last_exception():
>     return _ctx('last_exception', None)
> 
> def _context_for_exception(e):
>     """Get information for the context where an exception was raised
> 
>     It requires getting the exception as argument for safety, to make sure
>     information for the right exception is returned.
>     """
>     if e is _last_exception():
>         return CTX.last_exception_context
> 
> def context_for_exception(e):
>     return _context_str(_context_for_exception(e))
> 
> def _context_aware(fn, *args, **kwargs):
>     new_context("[%s function begin]" % (fn.__name__))
>     try:
>         try:
>             return fn(*args, **kwargs)
>         except Exception,e:
>             if e is not _last_exception():
>                 CTX.last_exception = e
>                 CTX.last_exception_context = CTX.context[:] # make a copy
>             raise
>     finally:
>         clear_context()
> 
> context_aware = decorator.decorator(_context_aware)
> 
> 
> ## test code:
> #############
> 
> import unittest
> class TestContext(unittest.TestCase):
>     def testSimpleCtx(self):
>         @context_aware
>         def a():
>             context("hello")
>             b()
>             context("world")
>             self.assertEquals(get_context(), 'world')
> 
>         @context_aware
>         def b():
>             context("foo")
>             c()
> 
>         @context_aware
>         def c():
>             context("bar")
>             self.assertEquals(get_context(), 'hello --> foo --> bar')
> 
>         a() # test it
>         self.assertEquals(get_context(), '') # no context after everything returned
> 
> 
>     def testException(self):
>         @context_aware
>         def try_something():
>             context("trying something")
>             raise Exception("something failed")
> 
>         @context_aware
>         def do_something():
>             context("do this")
>             context("do that")
>             context("try something")
>             try_something()
>             context("do something else")
> 
>         @context_aware
>         def main():
>             context("main code")
>             context("do something")
>             do_something()
> 
>         def test_exception():
>             try:
>                 main()
>             except Exception,e:
>                 ctx = context_for_exception(e)
>                 self.assertEquals(ctx, 'do something --> try something --> trying something')
>                 self.assertEquals(str(e), "something failed")
>             else:
>                 self.fail('exception not raised')
> 
>         test_exception()
>         self.assertEquals(get_context(), '') # no context after everything returned
> 
>     def testDroppedException(self):
>         @context_aware
>         def try_something():
>             context("trying something")
>             raise Exception("something failed")
> 
>         @context_aware
>         def do_something():
>             context("do this")
>             context("do that")
>             context("try something")
>             try:
>                 try_something()
>             except Exception,e:
>                 # function may do something here after handling the exception
>                 pass
>             context("do something else")
> 
>         @context_aware
>         def main():
>             context("main code")
>             context("do something")
>             do_something()
>             context("after do something")
>             raise Exception("another failure")
> 
>         def test_exception():
>             try:
>                 main()
>             except Exception,e:
>                 ctx = context_for_exception(e)
>                 self.assertEquals(ctx, 'after do something')
>                 self.assertEquals(str(e), "another failure")
>             else:
>                 self.fail('exception not raised')
> 
>         test_exception()
>         self.assertEquals(get_context(), '') # no context after everything returned
> 

Re: [Autotest] [KVM-AUTOTEST PATCH 3/7] [RFC] Introduce exception context strings

[Eduardo Habkost]

On Tue, Jan 04, 2011 at 12:56:16AM +0200, Michael Goldish wrote:
> On 01/04/2011 12:06 AM, Eduardo Habkost wrote:
> > On Mon, Jan 03, 2011 at 07:22:17PM -0200, Eduardo Habkost wrote:
[...]
> > If you want to be extra careful, you can keep an index of contexts for
> > each exception ever seen, and clear it in _call_test_function() code,
> > instead of keeping only the last exception. But I think we can keep it
> > simple and just store info for the last exception.
> 
> I think that's risky:
> 
> try:
>     vm.create()   # context aware, raises an exception
> except:
>     try:
>         vm.destroy()  # context aware, raises an exception
>     except:
>         pass
>     raise
> 
> The exception raised in VM.destroy() will override last_exception, and
> then whoever calls context_for_exception() will get the wrong context.

Correct.

> But I think this will work and it looks pretty clean:
> 
> def _context_aware(fn, *args, **kwargs):
>     new_context("")
>     try:
>         try:
>             return fn(*args, **kwargs)
>         except Exception, e:
>             if not hasattr(e, "context"):
>                 e.context = get_context()
>             raise sys.exc_info()[0], e, sys.exc_info()[2]

Wouldn't a simple "raise" (without any arguments) work here?

>     finally:
>         clear_context()

> This way we don't need to keep track of the last exception, and we even
> take care of the injection of .context here (instead of in test.py), so
> we don't need context_for_exception() at all.
> What do you think?

Looks good to me.

I did the 'is last_exception' trick because I assumed (incorrectly, I
guess) I couldn't set arbitrary attributes on Exception objects. I like
this solution (as long as you tested it and it works :).

> If this makes sense, I'd like to rewrite my patch using this decorator,
> unless you feel like doing so yourself.

Be my guest.  :)

-- 
Eduardo

Re: [KVM-AUTOTEST PATCH 3/7] [RFC] Introduce exception context strings

[Eduardo Habkost]

On Tue, Jan 04, 2011 at 12:56:16AM +0200, Michael Goldish wrote:
> I think that's risky:
> 
> try:
>     vm.create()   # context aware, raises an exception
> except:
>     try:
>         vm.destroy()  # context aware, raises an exception
>     except:
>         pass
>     raise

Heh, did you try the code above? It is a bit surprising (see below).

But I think your solution is cleaner, anyway, in case somebody does something
similar to the above while taking care to re-raise the right exception object.

-------
$ cat a.py 
def foo():
    raise Exception("foo")

def bar():
    raise Exception("bar")

try:
    foo()
except:
    print 'gotcha! (foo)'
    try:
        bar()
    except:
        print 'gotcha! (bar)'
        pass
    print 're-raising:'
    raise
$ python a.py 
gotcha! (foo)
gotcha! (bar)
re-raising:
Traceback (most recent call last):
  File "a.py", line 12, in <module>
    bar()
  File "a.py", line 5, in bar
    raise Exception("bar")
Exception: bar
$ 

-- 
Eduardo