bt2: don't print previous causes in causes created from bt2._Error
authorSimon Marchi <simon.marchi@efficios.com>
Mon, 2 Dec 2019 17:10:41 +0000 (12:10 -0500)
committerJérémie Galarneau <jeremie.galarneau@efficios.com>
Mon, 20 Jan 2020 20:15:24 +0000 (15:15 -0500)
When an API call from Python fails, we create a bt2._Error that will
take the bt_error from the current thread and assume its ownership.  If
that bt2._Error escapes the Python code and is caught by the Babeltrace
native code, we convert that bt2._Error to a new cause.  We call str()
on the bt2._Error (through bt_py_common_format_exception) to obtain the
text with which to create the new cause.  However, the str() for
bt2._Error textually formats all the existing causes.  As a result, the
text for the new cause includes the string formatting of all the
previous causes.  When the CLI, for example, ends up printing all error
causes successively, it becomes very confusing: the text of one cause
includes the text of previous causes.

What we want, in fact, is not an str() of the bt2._Error, but just a
message that includes the traceback (to know where in the Python code
the cause was created) and the message passed to bt2._Error.__init__.
The traceback is just a goodie: we don't include it for causes created
in C, but since it's easy to obtain in Python it is nice to have.  There
is also the fact the file:line information for causes created in Python
is bogus (which should be fixed at some point), so the traceback fills
in for that for the moment.

This patch changes
restore_current_thread_error_and_append_exception_chain_recursive to
do this for bt2._Error.  For other exceptions, we still call
bt_py_common_format_exception, which ends up calling their __str__.

Here's an example:

    Traceback (most recent call last):
      File "test_simple.py", line 32, in <module>
        graph.run()
      File "/home/smarchi/build/babeltrace/src/bindings/python/bt2/build/build_lib/bt2/graph.py", line 188, in run
        utils._handle_func_status(status, 'graph object stopped running')
      File "/home/smarchi/build/babeltrace/src/bindings/python/bt2/build/build_lib/bt2/utils.py", line 140, in _handle_func_status
        raise bt2._Error(msg)
    bt2.error._Error: graph object stopped running
    [libbabeltrace2] (/home/smarchi/src/babeltrace/src/lib/graph/graph.c:600)
    Component's "consume" method failed: status=ERROR, comp-addr=0x1f15f50, comp-name="snk", comp-log-level=NONE, comp-class-type=SINK, comp-class-name="DummySink", comp-class-partial-descr="", comp-class-is-frozen=1, comp-input-port-count=1, comp-output-port-count=0
    [snk: sink.DummySink] (/home/smarchi/src/babeltrace/src/bindings/python/bt2/bt2/native_bt_log_and_append_error.h:99)
    Traceback (most recent call last):
      File "test_simple.py", line 26, in _user_consume
        next(self._iter)
      File "/home/smarchi/build/babeltrace/src/bindings/python/bt2/build/build_lib/bt2/message_iterator.py", line 58, in __next__
        status, 'unexpected error: cannot advance the message iterator'
      File "/home/smarchi/build/babeltrace/src/bindings/python/bt2/build/build_lib/bt2/utils.py", line 140, in _handle_func_status
        raise bt2._Error(msg)
    bt2.error._Error: unexpected error: cannot advance the message iterator
    [libbabeltrace2] (/home/smarchi/src/babeltrace/src/lib/graph/iterator.c:928)
    Component input port message iterator's "next" method failed: iter-addr=0x1ec1980, iter-upstream-comp-name="src", iter-upstream-comp-log-level=NONE, iter-upstream-comp-class-type=SOURCE, iter-upstream-comp-class-name="SourceWithFailingIter", iter-upstream-comp-class-partial-descr="", iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR
    [src (out): src.SourceWithFailingIter] (/home/smarchi/src/babeltrace/src/bindings/python/bt2/bt2/native_bt_log_and_append_error.h:102)
    Traceback (most recent call last):
      File "/home/smarchi/build/babeltrace/src/bindings/python/bt2/build/build_lib/bt2/message_iterator.py", line 201, in _bt_next_from_native
        msg = next(self)
      File "test_simple.py", line 8, in __next__
        raise ValueError('User message iterator is failing')
    ValueError: User message iterator is failing

    [libbabeltrace2] (/home/smarchi/src/babeltrace/src/lib/graph/iterator.c:928)
    Component input port message iterator's "next" method failed: iter-addr=0x1ec1980, iter-upstream-comp-name="src", iter-upstream-comp-log-level=NONE, iter-upstream-comp-class-type=SOURCE, iter-upstream-comp-class-name="SourceWithFailingIter", iter-upstream-comp-class-partial-descr="", iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR
    [src (out): src.SourceWithFailingIter] (/home/smarchi/src/babeltrace/src/bindings/python/bt2/bt2/native_bt_log_and_append_error.h:102)
    Traceback (most recent call last):
      File "/home/smarchi/build/babeltrace/src/bindings/python/bt2/build/build_lib/bt2/message_iterator.py", line 201, in _bt_next_from_native
        msg = next(self)
      File "test_simple.py", line 8, in __next__
        raise ValueError('User message iterator is failing')
    ValueError: User message iterator is failing

Notice how the "ValueError: User message iterator is failing" cause
seems to appear twice?  The first of them is in fact part of the text of
the "bt2.error._Error: unexpected error: cannot advance the message
iterator" cause.  With this patch applied, the first one of these does
not appear.

Change-Id: I9b3e2e6f78f5ee2ba49a0956f6ef77dbb23dadc4
Signed-off-by: Simon Marchi <simon.marchi@efficios.com>
Reviewed-on: https://review.lttng.org/c/babeltrace/+/2557
Tested-by: jenkins <jenkins@lttng.org>
src/bindings/python/bt2/bt2/native_bt_log_and_append_error.h
src/py-common/py-common.c
src/py-common/py-common.h

index f3b57bca388ca06004b67320983983a8da2b6980..801a43c0fbf5614cff42586a3cdf0749da907264 100644 (file)
@@ -37,9 +37,10 @@ void restore_current_thread_error_and_append_exception_chain_recursive(
        PyObject *py_exc_cause_value;
        PyObject *py_exc_type = NULL;
        PyObject *py_exc_tb = NULL;
+       PyObject *py_bt_error_msg = NULL;
        GString *gstr = NULL;
 
-       /* If this exception has a cause, handle that one first. */
+       /* If this exception has a (Python) cause, handle that one first. */
        py_exc_cause_value = PyException_GetCause(py_exc_value);
        if (py_exc_cause_value) {
                restore_current_thread_error_and_append_exception_chain_recursive(
@@ -48,17 +49,20 @@ void restore_current_thread_error_and_append_exception_chain_recursive(
                        self_message_iterator, module_name);
        }
 
-       /*
-        * If the raised exception is a bt2._Error, restore the wrapped error.
-        */
+       py_exc_tb = PyException_GetTraceback(py_exc_value);
+
        if (PyErr_GivenExceptionMatches(py_exc_value, py_mod_bt2_exc_error_type)) {
+               /*
+                * If the raised exception is a bt2._Error, restore the wrapped
+                * error.
+                */
                PyObject *py_error_swig_ptr;
                const bt_error *error;
                int ret;
 
                /*
-                * We never raise a bt2._Error with a cause: it should be the
-                * end of the chain.
+                * We never raise a bt2._Error with a (Python) cause: it should
+                * be the end of the chain.
                 */
                BT_ASSERT(!py_exc_cause_value);
 
@@ -76,19 +80,37 @@ void restore_current_thread_error_and_append_exception_chain_recursive(
                        SWIGTYPE_p_bt_error, 0);
                BT_ASSERT(ret == 0);
 
+               Py_DECREF(py_error_swig_ptr);
+
                BT_CURRENT_THREAD_MOVE_ERROR_AND_RESET(error);
 
-               Py_DECREF(py_error_swig_ptr);
-       }
+               /*
+                * Append a cause with just the traceback and message, not the
+                * full str() of the bt2._Error.  We don't want the causes of
+                * this bt2._Error to be included in the cause we create.
+                */
+               gstr = bt_py_common_format_tb(py_exc_tb, active_log_level);
+               if (!gstr) {
+                       /* bt_py_common_format_tb has already warned. */
+                       goto end;
+               }
 
-       py_exc_type = PyObject_Type(py_exc_value);
-       py_exc_tb = PyException_GetTraceback(py_exc_value);
+               g_string_prepend(gstr, "Traceback (most recent call last):\n");
 
-       gstr = bt_py_common_format_exception(py_exc_type, py_exc_value,
-                       py_exc_tb, active_log_level, false);
-       if (!gstr) {
-               /* bt_py_common_format_exception has already warned. */
-               goto end;
+               py_bt_error_msg = PyObject_GetAttrString(py_exc_value, "_msg");
+               BT_ASSERT(py_bt_error_msg);
+
+               g_string_append_printf(gstr, "\nbt2._Error: %s",
+                       PyUnicode_AsUTF8(py_bt_error_msg));
+       } else {
+               py_exc_type = PyObject_Type(py_exc_value);
+
+               gstr = bt_py_common_format_exception(py_exc_type, py_exc_value,
+                               py_exc_tb, active_log_level, false);
+               if (!gstr) {
+                       /* bt_py_common_format_exception has already warned. */
+                       goto end;
+               }
        }
 
        if (self_component_class) {
@@ -113,6 +135,7 @@ end:
        Py_XDECREF(py_exc_cause_value);
        Py_XDECREF(py_exc_type);
        Py_XDECREF(py_exc_tb);
+       Py_XDECREF(py_bt_error_msg);
 }
 
 /*
index db8fd3daf6b51d55a720f00ffb1413190c36ec9a..b1ca34ae455014f87e85116c33fd8b2ab97e4a15 100644 (file)
 #include "common/assert.h"
 #include "py-common.h"
 
+/*
+ * Concatenate strings in list `py_str_list`, returning the result as a
+ * GString.  Remove the trailing \n, if the last string ends with a \n.
+ */
+static
+GString *py_str_list_to_gstring(PyObject *py_str_list, int log_level)
+{
+       Py_ssize_t i;
+       GString *gstr;
+
+       gstr = g_string_new(NULL);
+       if (!gstr) {
+               BT_LOGE("Failed to allocate a GString.");
+               goto end;
+       }
+
+       for (i = 0; i < PyList_Size(py_str_list); i++) {
+               PyObject *py_str;
+               const char *str;
+
+               py_str = PyList_GetItem(py_str_list, i);
+               BT_ASSERT(py_str);
+               BT_ASSERT(PyUnicode_CheckExact(py_str));
+
+               /* `str` is owned by `py_str`, not by us */
+               str = PyUnicode_AsUTF8(py_str);
+               if (!str) {
+                       if (BT_LOG_ON_ERROR) {
+                               BT_LOGE_STR("PyUnicode_AsUTF8() failed:");
+                               PyErr_Print();
+                       }
+
+                       goto error;
+               }
+
+               /* `str` has a trailing newline */
+               g_string_append(gstr, str);
+       }
+
+       if (gstr->len > 0) {
+               /* Remove trailing newline if any */
+               if (gstr->str[gstr->len - 1] == '\n') {
+                       g_string_truncate(gstr, gstr->len - 1);
+               }
+       }
+
+       goto end;
+
+error:
+       g_string_free(gstr, TRUE);
+       gstr = NULL;
+
+end:
+       return gstr;
+}
+
+BT_HIDDEN
+GString *bt_py_common_format_tb(PyObject *py_exc_tb, int log_level)
+{
+       PyObject *traceback_module = NULL;
+       PyObject *format_tb_func = NULL;
+       PyObject *exc_str_list = NULL;
+       GString *msg_buf = NULL;
+
+       BT_ASSERT(py_exc_tb);
+
+       /*
+        * Import the standard `traceback` module which contains the
+        * functions to format a traceback.
+        */
+       traceback_module = PyImport_ImportModule("traceback");
+       if (!traceback_module) {
+               BT_LOGE_STR("Failed to import `traceback` module.");
+               goto error;
+       }
+
+       format_tb_func = PyObject_GetAttrString(traceback_module,
+               "format_tb");
+       if (!format_tb_func) {
+               BT_LOGE("Cannot find `format_tb` attribute in `traceback` module.");
+               goto error;
+       }
+
+       if (!PyCallable_Check(format_tb_func)) {
+               BT_LOGE("`traceback.format_tb` attribute is not callable.");
+               goto error;
+       }
+
+       /*
+        * If we are calling format_exception_only, `py_exc_tb` is NULL, so the
+        * effective argument list is of length 2.
+        */
+       exc_str_list = PyObject_CallFunctionObjArgs(
+               format_tb_func, py_exc_tb, NULL);
+       if (!exc_str_list) {
+               if (BT_LOG_ON_ERROR) {
+                       BT_LOGE("Failed to call `traceback.format_tb` function:");
+                       PyErr_Print();
+               }
+
+               goto error;
+       }
+
+       msg_buf = py_str_list_to_gstring(exc_str_list, log_level);
+       if (!msg_buf) {
+               goto error;
+       }
+
+       goto end;
+
+error:
+       if (msg_buf) {
+               g_string_free(msg_buf, TRUE);
+               msg_buf = NULL;
+       }
+
+end:
+       Py_XDECREF(traceback_module);
+       Py_XDECREF(format_tb_func);
+       Py_XDECREF(exc_str_list);
+
+       return msg_buf;
+}
+
 BT_HIDDEN
 GString *bt_py_common_format_exception(PyObject *py_exc_type,
                PyObject *py_exc_value, PyObject *py_exc_tb,
@@ -43,7 +167,6 @@ GString *bt_py_common_format_exception(PyObject *py_exc_type,
        PyObject *exc_str_list = NULL;
        GString *msg_buf = NULL;
        const char *format_exc_func_name;
-       Py_ssize_t i;
 
        /*
         * Import the standard `traceback` module which contains the
@@ -94,35 +217,9 @@ GString *bt_py_common_format_exception(PyObject *py_exc_type,
                goto error;
        }
 
-       msg_buf = g_string_new(NULL);
-
-       for (i = 0; i < PyList_Size(exc_str_list); i++) {
-               PyObject *exc_str;
-               const char *str;
-
-               exc_str = PyList_GetItem(exc_str_list, i);
-               BT_ASSERT(exc_str);
-
-               /* `str` is owned by `exc_str`, not by us */
-               str = PyUnicode_AsUTF8(exc_str);
-               if (!str) {
-                       if (BT_LOG_ON_ERROR) {
-                               BT_LOGE_STR("PyUnicode_AsUTF8() failed:");
-                               PyErr_Print();
-                       }
-
-                       goto error;
-               }
-
-               /* `str` has a trailing newline */
-               g_string_append(msg_buf, str);
-       }
-
-       if (msg_buf->len > 0) {
-               /* Remove trailing newline if any */
-               if (msg_buf->str[msg_buf->len - 1] == '\n') {
-                       g_string_truncate(msg_buf, msg_buf->len - 1);
-               }
+       msg_buf = py_str_list_to_gstring(exc_str_list, log_level);
+       if (!msg_buf) {
+               goto error;
        }
 
        goto end;
index 6622438a275c789ba88998fb3a43c96eddf138db..1ac5f21fc22680228ed0e8c08ea9459a3809e5ac 100644 (file)
 
 #include "common/macros.h"
 
+/*
+ * Formats the Python traceback `py_exc_tb` using traceback.format_tb, from the
+ * Python standard library, and return it as a Gstring.
+ */
+BT_HIDDEN
+GString *bt_py_common_format_tb(PyObject *py_exc_tb, int log_level);
+
 /*
  * Formats the Python exception described by `py_exc_type`, `py_exc_value`
  * and `py_exc_tb` and returns the formatted string, or `NULL` on error. The
This page took 0.030384 seconds and 4 git commands to generate.