Repository: SINTEF/dlite (language: python)

Issue:
Error messages from Python plugins
The changes in dlite_pyembed_verr() in dlite-pyembed.c  introduced in PRs #565 and #567 seems for some reasons to hide error messages produced when importing or calling methods in a plugin. 

Make sure that such error messages are reported. We should also figure out how to capture the traceback.




Discussion / hints:

Fix patch:
diff --git a/src/dlite-storage-plugins.c b/src/dlite-storage-plugins.c
index 567105da2..27be132ec 100644
--- a/src/dlite-storage-plugins.c
+++ b/src/dlite-storage-plugins.c
@@ -143,7 +143,7 @@ const DLiteStoragePlugin *dlite_storage_plugin_get(const char *name)
     size_t size=0, m=0;
     char *buf=NULL;
     r = asnpprintf(&buf, &size, m, "cannot find storage plugin for driver "
-                   "\"%s\" in search path:\n", name);
+                   "\"%s\" in\n   search path:\n", name);
     if (r >= 0) m += r;
     while (paths && (p = *(paths++)) && ++n) {
       r = asnpprintf(&buf, &size, m, "   - %s\n", p);
@@ -153,20 +153,39 @@ const DLiteStoragePlugin *dlite_storage_plugin_get(const char *name)
 #ifdef WITH_PYTHON
     FUPaths *ppaths = dlite_python_storage_paths();
     FUIter *iter = fu_startmatch("*.py", ppaths);
+    const char **failed_paths;
     r = asnpprintf(&buf, &size, m,
-                   "   ...the following Python plugins were also checked:\n");
+                   "   The following Python plugins were also checked:\n");
     if (r >= 0) m += r;
     while ((p = fu_nextmatch(iter))) {
       r = asnpprintf(&buf, &size, m, "   - %s\n", p);
       if (r >= 0) m += r;
     }
-#endif
 
+    if ((failed_paths = dlite_python_storage_failed_paths())) {
+      r = asnpprintf(&buf, &size, m,
+                     "   The following Python plugins failed to load:\n");
+      if (r >= 0) m += r;
+      while ((failed_paths && *failed_paths)) {
+        r = asnpprintf(&buf, &size, m, "   - %s\n", *(failed_paths++));
+        if (r >= 0) m += r;
+      }
+      if (!getenv("DLITE_PYDEBUG")) {
+        r = asnpprintf(&buf, &size, m,
+                       "   To see error messages from Python storages, please "
+                       "rerun with the\n"
+                       "   DLITE_PYDEBUG environment variable set.\n");
+        if (r >= 0) m += r;
+      }
+    }
+
+#endif
     if (n <= 1)
-      m += asnpprintf(&buf, &size, m, "Are the required Python packages "
-                      "installed or %sDLITE_STORAGE_PLUGIN_DIRS "
-                      "or DLITE_PYTHON_STORAGE_PLUGIN_DIRS "
-                      "environment variables set?", submsg);
+      m += asnpprintf(&buf, &size, m,
+                      "   Are the required Python packages installed or %s\n"
+                      "   DLITE_STORAGE_PLUGIN_DIRS or "
+                      "DLITE_PYTHON_STORAGE_PLUGIN_DIRS\n"
+                      "   environment variables set?", submsg);
     errx(1, "%s", buf);
     free(buf);
   }
diff --git a/src/pyembed/dlite-pyembed-utils.c b/src/pyembed/dlite-pyembed-utils.c
index 4df0e61ce..c81676b03 100644
--- a/src/pyembed/dlite-pyembed-utils.c
+++ b/src/pyembed/dlite-pyembed-utils.c
@@ -1,5 +1,6 @@
-#include <Python.h>
+#include "dlite-misc.h"
 #include "dlite-pyembed.h"
+#include "dlite-pyembed-utils.h"
 
 
 /*
diff --git a/src/pyembed/dlite-pyembed.c b/src/pyembed/dlite-pyembed.c
index 5b2bc085a..a474eeea3 100644
--- a/src/pyembed/dlite-pyembed.c
+++ b/src/pyembed/dlite-pyembed.c
@@ -131,102 +131,119 @@ const char *dlite_pyembed_classname(PyObject *cls)
 
 
 /*
-  Reports and resets Python error.
-
-  If an Python error has occured, an error message is appended to `msg`,
-  containing the type, value and traceback.
+  Writes Python error message to `errmsg` (of length `len`) if an
+  Python error has occured.
 
-  Returns `eval`.
- */
-int dlite_pyembed_err(int eval, const char *msg, ...)
-{
-  int stat;
-  va_list ap;
-  va_start(ap, msg);
-  stat = dlite_pyembed_verr(eval, msg, ap);
-  va_end(ap);
-  return stat;
-}
+  On return the The Python error indicator is reset.
 
-/*
-  Like dlite_pyembed_err() but takes a `va_list` as input.
- */
-int dlite_pyembed_verr(int eval, const char *msg, va_list ap)
+  Returns 0 if no error has occured.  Otherwise return the number of
+  bytes written to, or would have been written to `errmsg` if it had
+  been large enough.  On error -1 is returned.
+*/
+int dlite_pyembed_errmsg(char *errmsg, size_t errlen)
 {
   PyObject *type, *value, *tb;
-  char errmsg[4096];
-  errmsg[0] = '\0';
+  int n=-1;
 
-  /* Check if an error has occurred.  We use PyErr_Fetch() rather than
-     PyErr_Occurred() since we don't want to mess with ensuring that
-     we hold the GIL. */
   PyErr_Fetch(&type, &value, &tb);
-  if (!type) return dlite_verr(eval, msg, ap);  // no Python error
-
-  /* If the DLITE_PYDEBUG environment variable is set, print full Python
-     error message (with traceback) to sys.stderr.
-     Before doing that, we have to temporary restore the error state. */
-  if (getenv("DLITE_PYDEBUG")) {
-    PyErr_Restore(type, value, tb);
-    PySys_WriteStderr("\n");
-    PyErr_PrintEx(0);
-    PySys_WriteStderr("\n");
-    PyErr_Fetch(&type, &value, &tb);
-  }
-
-  /* Normalize the fetched exception */
+  if (!type) return 0;
   PyErr_NormalizeException(&type, &value, &tb);
-  assert(type);
 
   /* Try to create a error message from Python using the treaceback package */
-  PyObject *module_name=NULL, *module=NULL, *pfunc=NULL, *val=NULL,
-    *sep=NULL, *str=NULL;
-  if ((module_name = PyUnicode_FromString("traceback")) &&
-      (module = PyImport_Import(module_name)) &&
-      (pfunc = PyObject_GetAttrString(module, "format_exception")) &&
-      PyCallable_Check(pfunc) &&
-      (val = PyObject_CallFunctionObjArgs(pfunc, type, value, tb, NULL)) &&
-      PySequence_Check(val) &&
-      (sep = PyUnicode_FromString("")) &&
-      (str = PyUnicode_Join(val, sep)) &&
-      PyUnicode_Check(str) &&
-      PyUnicode_GET_LENGTH(str) > 0)
-    PyOS_snprintf(errmsg, sizeof(errmsg), "%s\n%s",
-                  msg, (char *)PyUnicode_AsUTF8(str));
-  Py_XDECREF(str);
-  Py_XDECREF(sep);
-  Py_XDECREF(val);
-  Py_XDECREF(pfunc);
-  Py_XDECREF(module);
-  Py_XDECREF(module_name);
+  if (errmsg) {
+    PyObject *module_name=NULL, *module=NULL, *pfunc=NULL, *val=NULL,
+      *sep=NULL, *str=NULL;
+    errmsg[0] = '\0';
+    if ((module_name = PyUnicode_FromString("traceback")) &&
+        (module = PyImport_Import(module_name)) &&
+        (pfunc = PyObject_GetAttrString(module, "format_exception")) &&
+        PyCallable_Check(pfunc) &&
+        (val = PyObject_CallFunctionObjArgs(pfunc, type, value, tb, NULL)) &&
+        PySequence_Check(val) &&
+        (sep = PyUnicode_FromString("")) &&
+        (str = PyUnicode_Join(val, sep)) &&
+        PyUnicode_Check(str) &&
+        PyUnicode_GET_LENGTH(str) > 0)
+      n = PyOS_snprintf(errmsg, errlen, "%s", (char *)PyUnicode_AsUTF8(str));
+    Py_XDECREF(str);
+    Py_XDECREF(sep);
+    Py_XDECREF(val);
+    Py_XDECREF(pfunc);
+    Py_XDECREF(module);
+    Py_XDECREF(module_name);
+  }
 
   /* ...otherwise try to report error without traceback... */
-  if (!errmsg[0]) {
+  if (errmsg && n < 0) {
     PyObject *name=NULL, *sname=NULL, *svalue=NULL;
     if ((name = PyObject_GetAttrString(type, "__name__")) &&
         (sname = PyObject_Str(name)) &&
         PyUnicode_Check(sname) &&
         (svalue = PyObject_Str(value)) &&
         PyUnicode_Check(svalue))
-      PyOS_snprintf(errmsg, sizeof(errmsg), "%s: %s: %s",
-                    msg, (char *)PyUnicode_AsUTF8(sname),
-                    (char *)PyUnicode_AsUTF8(svalue));
+      n = PyOS_snprintf(errmsg, errlen, "%s: %s",
+                        (char *)PyUnicode_AsUTF8(sname),
+                        (char *)PyUnicode_AsUTF8(svalue));
+
     Py_XDECREF(svalue);
     Py_XDECREF(sname);
     Py_XDECREF(name);
   }
 
-  /* ...otherwise skip Python error info */
-  if (!errmsg[0])
-    PyOS_snprintf(errmsg, sizeof(errmsg), "%s: <inaccessible Python error>",
-                  msg);
+  /* ...otherwise fallback to write to sys.stderr.
+     We also do this if the DLITE_PYDEBUG environment variable is set. */
+  if ((errmsg && n < 0) || getenv("DLITE_PYDEBUG")) {
+    PyErr_Restore(type, value, tb);
+    PySys_WriteStderr("\n");
+    PyErr_PrintEx(0);
+    PySys_WriteStderr("\n");
+  } else {
+    Py_DECREF(type);
+    Py_DECREF(value);
+    Py_XDECREF(tb);
+  }
+
+  return (errmsg) ? n : 0;
+}
+
+
+/*
+  Reports and resets Python error.
 
-  if (errmsg[0]) msg = errmsg;
+  If an Python error has occured, an error message is appended to `msg`,
+  containing the type, value and traceback.
 
-  Py_DECREF(type);
-  Py_DECREF(value);
-  Py_XDECREF(tb);
-  return dlite_verrx(eval, msg, ap);
+  Returns `eval`.
+ */
+int dlite_pyembed_err(int eval, const char *msg, ...)
+{
+  int stat;
+  va_list ap;
+  va_start(ap, msg);
+  stat = dlite_pyembed_verr(eval, msg, ap);
+  va_end(ap);
+  return stat;
+}
+
+/*
+  Like dlite_pyembed_err() but takes a `va_list` as input.
+ */
+int dlite_pyembed_verr(int eval, const char *msg, va_list ap)
+{
+  char errmsg[4096], *p=errmsg;
+  int m = sizeof(errmsg);
+  int n = vsnprintf(errmsg, sizeof(errmsg), msg, ap);
+  if (n > 0) {
+    p += n;
+    m -= n;
+    n = snprintf(p, m, ": ");
+    if (n > 0) {
+      p += n;
+      m -= n;
+    }
+  }
+  dlite_pyembed_errmsg(p, m);
+  return dlite_errx(eval, "%s", errmsg);
 }
 
 
@@ -428,7 +445,7 @@ PyObject *dlite_pyembed_load_plugins(FUPaths *paths, PyObject *baseclass,
   PyObject *main_dict, *ppath=NULL, *pfun=NULL, *subclasses=NULL, *lst=NULL;
   PyObject *subclassnames=NULL;
   FUIter *iter;
-  int i, pos=0;
+  int i;
   char errors[4098] = "";
 
   dlite_errclr();
@@ -478,30 +495,14 @@ PyObject *dlite_pyembed_load_plugins(FUPaths *paths, PyObject *baseclass,
           PyObject *ret = PyRun_File(fp, basename, Py_file_input, main_dict,
                                      main_dict);
           if (!ret) {
+
             if (failed_paths && failed_len) {
               char **new = strlst_append(*failed_paths, failed_len, path);
               if (!new) FAIL("allocation failure");
               *failed_paths = new;
             }
 
-            PyObject *type=NULL, *value=NULL, *tb=NULL, *name=NULL, *msg=NULL;
-            PyErr_Fetch(&type, &value, &tb);
-            int showtb = tb && tb != Py_None && getenv("DLITE_PYDEBUG");
-            name = PyObject_GetAttrString(type, "__name__");
-            msg = PyObject_Str(value);
-            int m = snprintf(errors+pos, sizeof(errors)-pos,
-                             "   - %s: %s: %s%s%s\n",
-                             path,
-                             PyUnicode_AsUTF8(name),
-                             PyUnicode_AsUTF8(msg),
-                             (showtb) ? "\n": "",
-                             (showtb) ? PyUnicode_AsUTF8(tb) : "");
-            if (m > 0) pos += m;
-            Py_XDECREF(type);
-            Py_XDECREF(value);
-            Py_XDECREF(tb);
-            Py_XDECREF(name);
-            Py_XDECREF(msg);
+            dlite_pyembed_errmsg(NULL, 0);
             fclose(fp);
           }
           Py_XDECREF(ret);
diff --git a/src/pyembed/dlite-pyembed.h b/src/pyembed/dlite-pyembed.h
index 12d089c38..4e27fcd5d 100644
--- a/src/pyembed/dlite-pyembed.h
+++ b/src/pyembed/dlite-pyembed.h
@@ -36,6 +36,18 @@ int dlite_pyembed_finalise(void);
 const char *dlite_pyembed_classname(PyObject *cls);
 
 
+/**
+  Writes Python error message to `errmsg` (of length `len`) if an
+  Python error has occured.
+
+  On return the The Python error indicator is reset.
+
+  Returns 0 if no error has occured, otherwise return the number of
+  bytes written to `errmsg`. On error -1 is returned.
+*/
+int dlite_pyembed_errmsg(char *errmsg, size_t errlen);
+
+
 /**
   Reports and restes Python error.
 
diff --git a/src/pyembed/dlite-python-storage.c b/src/pyembed/dlite-python-storage.c
index 13a5539b4..aa556c00a 100644
--- a/src/pyembed/dlite-python-storage.c
+++ b/src/pyembed/dlite-python-storage.c
@@ -56,7 +56,6 @@ static void free_globals(void *globals)
   free(g);
 }
 
-
 /* Return a pointer to global state for this module */
 static PythonStorageGlobals *get_globals(void)
 {
@@ -70,6 +69,17 @@ static PythonStorageGlobals *get_globals(void)
 }
 
 
+/*
+  Returns a static pointer to a NULL-terminated list of pointers to
+  storages that failed to load.
+*/
+const char **dlite_python_storage_failed_paths()
+{
+  PythonStorageGlobals *g = get_globals();
+  return (const char **)g->failed_paths;
+}
+
+
 /*
   Returns a pointer to Python storage paths
 */
diff --git a/src/pyembed/dlite-python-storage.h b/src/pyembed/dlite-python-storage.h
index 2c02c9d2a..168e66096 100644
--- a/src/pyembed/dlite-python-storage.h
+++ b/src/pyembed/dlite-python-storage.h
@@ -8,9 +8,14 @@
 #ifdef HAVE_CONFIG_H
 #undef HAVE_CONFIG_H
 #endif
-//#include "utils/fileutils.h"
 
 
+/**
+  Returns a static pointer to a NULL-terminated list of pointers to
+  storages that failed to load.
+*/
+const char **dlite_python_storage_failed_paths();
+
 /**
   Returns a pointer to internal Python storage search paths.
 */


Test patch:
diff --git a/bindings/python/tests/test_storage.py b/bindings/python/tests/test_storage.py
index ad31e2b81..97244df29 100755
--- a/bindings/python/tests/test_storage.py
+++ b/bindings/python/tests/test_storage.py
@@ -21,7 +21,7 @@
 
 
 # Create an instance
-inst = myentity(dims=[2, 3], id='my-data')
+inst = myentity(dimensions=[2, 3], id='my-data')
 inst['a-bool-array'] = True, False
 
 # Test Storage.save()