Libguestfs - Aug 2018 - Re: [PATCH nbdkit] python: Try harder to print the full traceback on error.

The tracebacks are compressed into a single line because we're using
PyObject_Str, but they are just about usable if not very readable.
For example you would see an error like this:

nbdkit: error: ./python-exception.py: config_complete: error: ['Traceback
(most recent call last):\n', '  File "./python-exception.py",
line 54, in config_complete\n    raise_error1()\n', '  File
"./python-exception.py", line 48, in raise_error1\n   
raise_error2()\n', '  File "./python-exception.py", line 45,
in raise_error2\n    raise RuntimeError("this is the test
string")\n', 'RuntimeError: this is the test string\n']

which can be read by manually unfolding the exception in an editor as:

nbdkit: error: ./python-exception.py: config_complete: error:
Traceback (most recent call last):
  File "./python-exception.py", line 54, in config_complete
    raise_error1()
  File "./python-exception.py", line 48, in raise_error1
    raise_error2()
  File "./python-exception.py", line 45, in raise_error2
    raise RuntimeError("this is the test string")
RuntimeError: this is the test string

This also fixes the Python exception test which, it turned out, was
not testing anything.  It now tests both simple exceptions and
tracebacks.

Tested with Python 2.7.15 & 3.6.6.
---
 plugins/python/python.c        | 92 ++++++++++++++++++++++++++++------
 tests/python-exception.py      | 20 +++++++-
 tests/test-python-exception.sh | 13 ++++-
 3 files changed, 109 insertions(+), 16 deletions(-)

diff --git a/plugins/python/python.c b/plugins/python/python.c
index 7eb91d7..3450b9b 100644
--- a/plugins/python/python.c
+++ b/plugins/python/python.c
@@ -129,27 +129,91 @@ python_to_string (PyObject *str)
   return NULL;
 }
 
+/* This is the fallback in case we cannot get the full traceback. */
+static void
+print_python_error (const char *callback, PyObject *error)
+{
+  PyObject *error_str;
+  char *error_cstr = NULL;
+
+  error_str = PyObject_Str (error);
+  error_cstr = python_to_string (error_str);
+  nbdkit_error ("%s: %s: error: %s",
+                script, callback,
+                error_cstr ? error_cstr : "<unknown>");
+  Py_DECREF (error_str);
+  free (error_cstr);
+}
+
+/* Convert the Python traceback to a string and call nbdkit_error.
+ * https://stackoverflow.com/a/15907460/7126113
+ */
+static int
+print_python_traceback (const char *callback,
+                        PyObject *type, PyObject *error, PyObject *traceback)
+{
+  PyObject *module_name, *traceback_module, *format_exception_fn, *rv,
+    *traceback_str;
+  char *traceback_cstr;
+
+#ifdef HAVE_PYSTRING_FROMSTRING
+  module_name = PyString_FromString ("traceback");
+#else
+  module_name = PyUnicode_FromString ("traceback");
+#endif
+  traceback_module = PyImport_Import (module_name);
+  Py_DECREF (module_name);
+
+  /* couldn't 'import traceback' */
+  if (traceback_module == NULL)
+    return -1;
+
+  format_exception_fn = PyObject_GetAttrString (traceback_module,
+                                                "format_exception");
+  if (format_exception_fn == NULL)
+    return -1;
+  if (!PyCallable_Check (format_exception_fn))
+    return -1;
+
+  rv = PyObject_CallFunctionObjArgs (format_exception_fn,
+                                     type, error, traceback, NULL);
+  traceback_str = PyObject_Str (rv);
+  traceback_cstr = python_to_string (traceback_str);
+  if (traceback_cstr == NULL) {
+    Py_DECREF (rv);
+    return -1;
+  }
+
+  nbdkit_error ("%s: %s: error: %s",
+                script, callback,
+                traceback_cstr);
+  Py_DECREF (rv);
+  free (traceback_cstr);
+
+  /* This means we succeeded in calling nbdkit_error. */
+  return 0;
+}
+
 static int
 check_python_failure (const char *callback)
 {
   if (PyErr_Occurred ()) {
-    PyObject *type, *error, *traceback, *error_str;
-    char *error_cstr;
+    PyObject *type, *error, *traceback;
 
-    /* Convert the Python exception to a string.
-     * https://stackoverflow.com/a/1418703
-     * But forget about the traceback, it's very hard to print.
-     * https://stackoverflow.com/q/1796510
-     */
     PyErr_Fetch (&type, &error, &traceback);
     PyErr_NormalizeException (&type, &error, &traceback);
-    error_str = PyObject_Str (error);
-    error_cstr = python_to_string (error_str);
-    nbdkit_error ("%s: %s: error: %s",
-                  script, callback,
-                  error_cstr ? error_cstr : "<unknown>");
-    Py_DECREF (error_str);
-    free (error_cstr);
+
+    /* Try to print the full traceback. */
+    if (print_python_traceback (callback, type, error, traceback) == -1) {
+      /* Couldn't do that, so fall back to converting the Python error
+       * to a string.
+       */
+      print_python_error (callback, error);
+    }
+
+    /* In all cases this returns -1 to indicate that a Python error
+     * occurred.
+     */
     return -1;
   }
   return 0;
diff --git a/tests/python-exception.py b/tests/python-exception.py
index 1debf51..739057f 100644
--- a/tests/python-exception.py
+++ b/tests/python-exception.py
@@ -32,10 +32,28 @@
 
 # A dummy python plugin which just raises an exception in config_complete.
 
+test = "simple"
 
-def config_complete():
+def config(k, v):
+    global test
+    if k == "test":
+        test = v
+    else:
+        raise RuntimeError("unknown config parameter")
+
+def raise_error2():
     raise RuntimeError("this is the test string")
 
+def raise_error1():
+    raise_error2()
+
+def config_complete():
+    if test == "simple":
+        raise RuntimeError("this is the test string")
+    elif test == "traceback":
+        raise_error1()
+    else:
+        raise RuntimeError("unknown test")
 
 def open(readonly):
     return 1
diff --git a/tests/test-python-exception.sh b/tests/test-python-exception.sh
index 83999af..7120132 100755
--- a/tests/test-python-exception.sh
+++ b/tests/test-python-exception.sh
@@ -31,12 +31,23 @@
 # OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
 # SUCH DAMAGE.
 
+set -e
+set -x
+
 output=test-python-exception.out
 
 rm -f $output
 
-nbdkit -f -v python ./python-exception.py > $output 2>&1 ||:
+nbdkit -f -v python ./python-exception.py test=simple > $output 2>&1
||:
+cat $output
 
 grep 'this is the test string' $output
 
+nbdkit -f -v python ./python-exception.py test=traceback > $output
2>&1 ||:
+cat $output
+
+grep 'raise_error1' $output
+grep 'raise_error2' $output
+grep 'this is the test string' $output
+
 rm $output
-- 
2.18.0

On Wed, Aug 8, 2018 at 4:07 PM Richard W.M. Jones <rjones@redhat.com>
wrote:
> The tracebacks are compressed into a single line because we're using
> PyObject_Str, but they are just about usable if not very readable.
> For example you would see an error like this:
>
> nbdkit: error: ./python-exception.py: config_complete: error:
['Traceback
> (most recent call last):\n', '  File
"./python-exception.py", line 54, in
> config_complete\n    raise_error1()\n', '  File
"./python-exception.py",
> line 48, in raise_error1\n    raise_error2()\n', '  File
> "./python-exception.py", line 45, in raise_error2\n    raise
> RuntimeError("this is the test string")\n',
'RuntimeError: this is the test
> string\n']
>
> which can be read by manually unfolding the exception in an editor as:
>
> nbdkit: error: ./python-exception.py: config_complete: error:
> Traceback (most recent call last):
>   File "./python-exception.py", line 54, in config_complete
>     raise_error1()
>   File "./python-exception.py", line 48, in raise_error1
>     raise_error2()
>   File "./python-exception.py", line 45, in raise_error2
>     raise RuntimeError("this is the test string")
> RuntimeError: this is the test string
>
It would be nicer to join the lines before logging, but having the info in
the log is good enough.

>
> This also fixes the Python exception test which, it turned out, was
> not testing anything.  It now tests both simple exceptions and
> tracebacks.
>
> Tested with Python 2.7.15 & 3.6.6.
> ---
>  plugins/python/python.c        | 92 ++++++++++++++++++++++++++++------
>  tests/python-exception.py      | 20 +++++++-
>  tests/test-python-exception.sh | 13 ++++-
>  3 files changed, 109 insertions(+), 16 deletions(-)
>
> diff --git a/plugins/python/python.c b/plugins/python/python.c
> index 7eb91d7..3450b9b 100644
> --- a/plugins/python/python.c
> +++ b/plugins/python/python.c
> @@ -129,27 +129,91 @@ python_to_string (PyObject *str)
>    return NULL;
>  }
>
> +/* This is the fallback in case we cannot get the full traceback. */
> +static void
> +print_python_error (const char *callback, PyObject *error)
> +{
> +  PyObject *error_str;
> +  char *error_cstr = NULL;
> +
> +  error_str = PyObject_Str (error);
> +  error_cstr = python_to_string (error_str);
+  nbdkit_error ("%s: %s: error: %s",
> +                script, callback,
> +                error_cstr ? error_cstr : "<unknown>");
> +  Py_DECREF (error_str);
> +  free (error_cstr);
> +}
> +
> +/* Convert the Python traceback to a string and call nbdkit_error.
> + * https://stackoverflow.com/a/15907460/7126113
> + */
> +static int
> +print_python_traceback (const char *callback,
> +                        PyObject *type, PyObject *error, PyObject
> *traceback)
> +{
> +  PyObject *module_name, *traceback_module, *format_exception_fn, *rv,
> +    *traceback_str;
> +  char *traceback_cstr;
> +
> +#ifdef HAVE_PYSTRING_FROMSTRING
> +  module_name = PyString_FromString ("traceback");
> +#else
> +  module_name = PyUnicode_FromString ("traceback");
> +#endif
> +  traceback_module = PyImport_Import (module_name);
> +  Py_DECREF (module_name);
> +
> +  /* couldn't 'import traceback' */
> +  if (traceback_module == NULL)
> +    return -1;
> +
> +  format_exception_fn = PyObject_GetAttrString (traceback_module,
> +                                               
"format_exception");
> +  if (format_exception_fn == NULL)
> +    return -1;
> +  if (!PyCallable_Check (format_exception_fn))
> +    return -1;
> +
> +  rv = PyObject_CallFunctionObjArgs (format_exception_fn,
> +                                     type, error, traceback, NULL);
> +  traceback_str = PyObject_Str (rv);
> +  traceback_cstr = python_to_string (traceback_str);
> +  if (traceback_cstr == NULL) {
> +    Py_DECREF (rv);
> +    return -1;
> +  }
> +
> +  nbdkit_error ("%s: %s: error: %s",
> +                script, callback,
> +                traceback_cstr);
>
Can we simplify this these 2 calls?

    nbdkit_error ("%s: %s: error", script, callback);
    PyErr_PrintEx (0);

See https://docs.python.org/3.6/c-api/exceptions.html#c.PyErr_PrintEx

In this case we don't to fallback to the simple error print.

> +  Py_DECREF (rv);
> +  free (traceback_cstr);
> +
> +  /* This means we succeeded in calling nbdkit_error. */
> +  return 0;
> +}
> +
>  static int
>  check_python_failure (const char *callback)
>  {
>    if (PyErr_Occurred ()) {
> -    PyObject *type, *error, *traceback, *error_str;
> -    char *error_cstr;
> +    PyObject *type, *error, *traceback;
>
> -    /* Convert the Python exception to a string.
> -     * https://stackoverflow.com/a/1418703
> -     * But forget about the traceback, it's very hard to print.
> -     * https://stackoverflow.com/q/1796510
> -     */
>      PyErr_Fetch (&type, &error, &traceback);
>      PyErr_NormalizeException (&type, &error, &traceback);
> -    error_str = PyObject_Str (error);
> -    error_cstr = python_to_string (error_str);
> -    nbdkit_error ("%s: %s: error: %s",
> -                  script, callback,
> -                  error_cstr ? error_cstr : "<unknown>");
> -    Py_DECREF (error_str);
> -    free (error_cstr);
> +
> +    /* Try to print the full traceback. */
> +    if (print_python_traceback (callback, type, error, traceback) == -1) {
> +      /* Couldn't do that, so fall back to converting the Python error
> +       * to a string.
> +       */
> +      print_python_error (callback, error);
> +    }
> +
> +    /* In all cases this returns -1 to indicate that a Python error
> +     * occurred.
> +     */
>      return -1;
>    }
>    return 0;
> diff --git a/tests/python-exception.py b/tests/python-exception.py
> index 1debf51..739057f 100644
> --- a/tests/python-exception.py
> +++ b/tests/python-exception.py
> @@ -32,10 +32,28 @@
>
>  # A dummy python plugin which just raises an exception in config_complete.
>
> +test = "simple"
>
> -def config_complete():
> +def config(k, v):
> +    global test
> +    if k == "test":
> +        test = v
> +    else:
> +        raise RuntimeError("unknown config parameter")
> +
> +def raise_error2():
>      raise RuntimeError("this is the test string")
>
> +def raise_error1():
> +    raise_error2()
> +
> +def config_complete():
> +    if test == "simple":
> +        raise RuntimeError("this is the test string")
> +    elif test == "traceback":
> +        raise_error1()
> +    else:
> +        raise RuntimeError("unknown test")
>
>  def open(readonly):
>      return 1
> diff --git a/tests/test-python-exception.sh
> b/tests/test-python-exception.sh
> index 83999af..7120132 100755
> --- a/tests/test-python-exception.sh
> +++ b/tests/test-python-exception.sh
> @@ -31,12 +31,23 @@
>  # OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
>  # SUCH DAMAGE.
>
> +set -e
> +set -x
> +
>  output=test-python-exception.out
>
>  rm -f $output
>
> -nbdkit -f -v python ./python-exception.py > $output 2>&1 ||:
> +nbdkit -f -v python ./python-exception.py test=simple > $output
2>&1 ||:
> +cat $output
>
>  grep 'this is the test string' $output
>
> +nbdkit -f -v python ./python-exception.py test=traceback > $output
2>&1
> ||:
> +cat $output
> +
> +grep 'raise_error1' $output
> +grep 'raise_error2' $output
> +grep 'this is the test string' $output
> +
>  rm $output
> --
> 2.18.0
>
>

On Wed, Aug 08, 2018 at 06:08:45PM +0300, Nir Soffer
wrote:
> Can we simplify this these 2 calls?
> 
>     nbdkit_error ("%s: %s: error", script, callback);
>     PyErr_PrintEx (0);
No, we want to ensure errors go through the nbdkit_error function so
that we can in future implement syslog logging.
> In this case we don't to fallback to the simple error print.
Do you mean in the case of using PyErr_PrintEx or more generally
falling back is a problem?

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
virt-builder quickly builds VMs from scratch
http://libguestfs.org/virt-builder.1.html