Paddle error message stack shaping and optimization (#19895)

* shape and optimize paddle error message stack, test=develop

* limit exception type & add unittest, test=develop

* fix multi-platform problem, test=develop

* fix related unnitest failed, test=develop

* add doc & fix unittest errors, test=develop

* fix function name error, test=develop

* update tensor test exception msg compare, test=develop

* remove unittest on win32, the dir format is different, test=develop

* remove useless package, test=develop

* add paddle enforce handler unittest, test=develop

* add exception checkout, test=develop

* fix coverage failed, test=develop

* fix op registry test failed, test=develop

* refactor whole pr, test=develop

* remove test in CMakelist, test=develop

* fix coverage, test=develop

paddle/fluid/framework/op_call_stack.cc

@@ -29,17 +29,35 @@ void InsertCallStackInfo(const std::string &type, const AttributeMap &attrs,
   auto &callstack = boost::get<std::vector<std::string>>(
       attrs.at(OpProtoAndCheckerMaker::OpCreationCallstackAttrName()));
 
-  if (callstack.empty()) {
-    return;
-  }
   std::ostringstream sout;
-  sout << "Invoke operator " << type << " error.\n";
-  sout << "Python Call stacks: \n";
-  for (auto &line : callstack) {
-    sout << line;
+  std::ostringstream sout_py_trace;
+  // Step 1. Construct python call stack string
+  if (!callstack.empty()) {
+    sout_py_trace << "\n------------------------------------------\n";
+    sout_py_trace << "Python Call Stacks (More useful to users):";
+    sout_py_trace << "\n------------------------------------------\n";
+    for (auto &line : callstack) {
+      sout_py_trace << line;
+    }
   }
-  sout << "C++ Call stacks: \n";
+  // Step 2. Insert python traceback into err_str_
+  std::size_t found = exception->err_str_.rfind("PaddleCheckError:");
+  if (found != std::string::npos) {
+    exception->err_str_.insert(found, sout_py_trace.str());
+    exception->err_str_.insert(found + sout_py_trace.str().length(),
+                               "\n----------------------\nError Message "
+                               "Summary:\n----------------------\n");
+  } else {
+    exception->err_str_.append(sout_py_trace.str());
+  }
+  // Step 3. Construct final call stack
+  sout << "\n\n--------------------------------------------\n";
+  sout << "C++ Call Stacks (More useful to developers):";
+  sout << "\n--------------------------------------------\n";
   sout << exception->err_str_;
+  if (!callstack.empty()) {
+    sout << "  [operator < " << type << " > error]";
+  }
   exception->err_str_ = sout.str();
 }
 

paddle/fluid/framework/op_registry_test.cc

@@ -118,10 +118,8 @@ TEST(OpRegistry, IllegalAttr) {
   } catch (paddle::platform::EnforceNotMet err) {
     caught = true;
     std::string msg = "larger_than check fail";
-    const char* err_msg = err.what();
-    for (size_t i = 0; i < msg.length(); ++i) {
-      ASSERT_EQ(err_msg[i], msg[i]);
-    }
+    std::string err_msg = err.what();
+    ASSERT_TRUE(err_msg.find(msg) != std::string::npos);
   }
   ASSERT_TRUE(caught);
 }
@@ -154,10 +152,8 @@ TEST(OpRegistry, CustomChecker) {
   } catch (paddle::platform::EnforceNotMet err) {
     caught = true;
     std::string msg = "Attribute 'test_attr' is required!";
-    const char* err_msg = err.what();
-    for (size_t i = 0; i < msg.length(); ++i) {
-      ASSERT_EQ(err_msg[i], msg[i]);
-    }
+    std::string err_msg = err.what();
+    ASSERT_TRUE(err_msg.find(msg) != std::string::npos);
   }
   ASSERT_TRUE(caught);
 
@@ -172,10 +168,8 @@ TEST(OpRegistry, CustomChecker) {
   } catch (paddle::platform::EnforceNotMet err) {
     caught = true;
     std::string msg = "'test_attr' must be even!";
-    const char* err_msg = err.what();
-    for (size_t i = 0; i < msg.length(); ++i) {
-      ASSERT_EQ(err_msg[i], msg[i]);
-    }
+    std::string err_msg = err.what();
+    ASSERT_TRUE(err_msg.find(msg) != std::string::npos);
   }
   ASSERT_TRUE(caught);
 

paddle/fluid/framework/tensor_test.cc

@@ -38,13 +38,11 @@ TEST(Tensor, DataAssert) {
     src_tensor.data<double>();
   } catch (platform::EnforceNotMet err) {
     caught = true;
-    std::string msg =
-        "holder_ should not be null\nTensor holds no memory. Call "
-        "Tensor::mutable_data first.";
-    const char* what = err.what();
-    for (size_t i = 0; i < msg.length(); ++i) {
-      ASSERT_EQ(what[i], msg[i]);
-    }
+    std::string ex_msg = err.what();
+    EXPECT_TRUE(ex_msg.find("holder_ should not be null\nTensor holds no "
+                            "memory. Call "
+                            "Tensor::mutable_data first.") !=
+                std::string::npos);
   }
   ASSERT_TRUE(caught);
 }
@@ -155,13 +153,11 @@ TEST(Tensor, ShareDataWith) {
       dst_tensor.ShareDataWith(src_tensor);
     } catch (paddle::platform::EnforceNotMet err) {
       caught = true;
-      std::string msg =
-          "holder_ should not be null\nTensor holds no memory. Call "
-          "Tensor::mutable_data first.";
-      const char* what = err.what();
-      for (size_t i = 0; i < msg.length(); ++i) {
-        ASSERT_EQ(what[i], msg[i]);
-      }
+      std::string ex_msg = err.what();
+      EXPECT_TRUE(ex_msg.find("holder_ should not be null\nTensor holds no "
+                              "memory. Call "
+                              "Tensor::mutable_data first.") !=
+                  std::string::npos);
     }
     ASSERT_TRUE(caught);
 

paddle/fluid/platform/enforce.h

@@ -52,6 +52,8 @@ limitations under the License. */
 #endif  // __APPLE__
 #endif  // PADDLE_WITH_CUDA
 
+#define WITH_SIMPLE_TRACEBACK
+
 namespace paddle {
 namespace platform {
 
@@ -72,18 +74,22 @@ inline std::string GetTraceBackString(StrType&& what, const char* file,
   static constexpr int TRACE_STACK_LIMIT = 100;
   std::ostringstream sout;
 
-  sout << string::Sprintf("%s at [%s:%d]", std::forward<StrType>(what), file,
-                          line)
-       << std::endl;
-  sout << "PaddlePaddle Call Stacks: " << std::endl;
 #if !defined(_WIN32)
   void* call_stack[TRACE_STACK_LIMIT];
   auto size = backtrace(call_stack, TRACE_STACK_LIMIT);
   auto symbols = backtrace_symbols(call_stack, size);
   Dl_info info;
+  int idx = 0;
   for (int i = 0; i < size; ++i) {
     if (dladdr(call_stack[i], &info) && info.dli_sname) {
       auto demangled = demangle(info.dli_sname);
+#ifdef WITH_SIMPLE_TRACEBACK
+      std::string path(info.dli_fname);
+      // C++ traceback info are from core.so
+      if (path.substr(path.length() - 3).compare(".so") == 0) {
+        sout << string::Sprintf("%-3d %s\n", idx++, demangled);
+      }
+#else
       auto addr_offset = static_cast<char*>(call_stack[i]) -
                          static_cast<char*>(info.dli_saddr);
       sout << string::Sprintf("%-3d %*0p %s + %zd\n", i, 2 + sizeof(void*) * 2,
@@ -91,12 +97,16 @@ inline std::string GetTraceBackString(StrType&& what, const char* file,
     } else {
       sout << string::Sprintf("%-3d %*0p\n", i, 2 + sizeof(void*) * 2,
                               call_stack[i]);
+#endif
     }
   }
   free(symbols);
 #else
   sout << "Windows not support stack backtrace yet.";
 #endif
+  sout << string::Sprintf("PaddleCheckError: %s at [%s:%d]",
+                          std::forward<StrType>(what), file, line)
+       << std::endl;
   return sout.str();
 }
 
@@ -338,7 +348,7 @@ DEFINE_CUDA_STATUS_TYPE(ncclResult_t, ncclSuccess);
  *    PADDLE_ENFORCE_EQ(a, b);
  *
  *    will raise an expression described as follows:
- *    "Enforce failed. Expected input a == b, but received a(1) != b(2)."
+ *    "Expected input a == b, but received a(1) != b(2)."
  *      with detailed stack information.
  *
  *    extra messages is also supported, for example:
@@ -445,8 +455,8 @@ struct BinaryCompareMessageConverter<false> {
       constexpr bool __kCanToString__ =                                        \
           ::paddle::platform::details::CanToString<__TYPE1__>::kValue &&       \
           ::paddle::platform::details::CanToString<__TYPE2__>::kValue;         \
-      PADDLE_THROW("Enforce failed. Expected %s " #__CMP                       \
-                   " %s, but received %s " #__INV_CMP " %s.\n%s",              \
+      PADDLE_THROW("Expected %s " #__CMP " %s, but received %s " #__INV_CMP    \
+                   " %s.\n%s",                                                 \
                    #__VAL1, #__VAL2,                                           \
                    ::paddle::platform::details::BinaryCompareMessageConverter< \
                        __kCanToString__>::Convert(#__VAL1, __val1),            \
@@ -469,32 +479,32 @@ struct BinaryCompareMessageConverter<false> {
 #define PADDLE_ENFORCE_LE(__VAL0, __VAL1, ...) \
   __PADDLE_BINARY_COMPARE(__VAL0, __VAL1, <=, >, __VA_ARGS__)
 
-#define __PADDLE_INFERSHAPE_BINARY_COMPARE(__CTX, __VAL1, __VAL2, __CMP, \
-                                           __INV_CMP, ...)               \
-  do {                                                                   \
-    auto __val1 = (__VAL1);                                              \
-    auto __val2 = (__VAL2);                                              \
-    if (!__CTX->IsRuntime()) {                                           \
-      if (__val1 == -1 || __val2 == -1) {                                \
-        break;                                                           \
-      }                                                                  \
-    }                                                                    \
-    using __TYPE1__ = decltype(__val1);                                  \
-    using __TYPE2__ = decltype(__val2);                                  \
-    using __COMMON_TYPE1__ =                                             \
-        ::paddle::platform::details::CommonType1<__TYPE1__, __TYPE2__>;  \
-    using __COMMON_TYPE2__ =                                             \
-        ::paddle::platform::details::CommonType2<__TYPE1__, __TYPE2__>;  \
-    bool __is_not_error = (static_cast<__COMMON_TYPE1__>(__val1))__CMP(  \
-        static_cast<__COMMON_TYPE2__>(__val2));                          \
-    if (UNLIKELY(!__is_not_error)) {                                     \
-      PADDLE_THROW("Enforce failed. Expected %s " #__CMP                 \
-                   " %s, but received %s:%s " #__INV_CMP " %s:%s.\n%s",  \
-                   #__VAL1, #__VAL2, #__VAL1,                            \
-                   ::paddle::string::to_string(__val1), #__VAL2,         \
-                   ::paddle::string::to_string(__val2),                  \
-                   ::paddle::string::Sprintf(__VA_ARGS__));              \
-    }                                                                    \
+#define __PADDLE_INFERSHAPE_BINARY_COMPARE(__CTX, __VAL1, __VAL2, __CMP,       \
+                                           __INV_CMP, ...)                     \
+  do {                                                                         \
+    auto __val1 = (__VAL1);                                                    \
+    auto __val2 = (__VAL2);                                                    \
+    if (!__CTX->IsRuntime()) {                                                 \
+      if (__val1 == -1 || __val2 == -1) {                                      \
+        break;                                                                 \
+      }                                                                        \
+    }                                                                          \
+    using __TYPE1__ = decltype(__val1);                                        \
+    using __TYPE2__ = decltype(__val2);                                        \
+    using __COMMON_TYPE1__ =                                                   \
+        ::paddle::platform::details::CommonType1<__TYPE1__, __TYPE2__>;        \
+    using __COMMON_TYPE2__ =                                                   \
+        ::paddle::platform::details::CommonType2<__TYPE1__, __TYPE2__>;        \
+    bool __is_not_error = (static_cast<__COMMON_TYPE1__>(__val1))__CMP(        \
+        static_cast<__COMMON_TYPE2__>(__val2));                                \
+    if (UNLIKELY(!__is_not_error)) {                                           \
+      PADDLE_THROW("Expected %s " #__CMP " %s, but received %s:%s " #__INV_CMP \
+                   " %s:%s.\n%s",                                              \
+                   #__VAL1, #__VAL2, #__VAL1,                                  \
+                   ::paddle::string::to_string(__val1), #__VAL2,               \
+                   ::paddle::string::to_string(__val2),                        \
+                   ::paddle::string::Sprintf(__VA_ARGS__));                    \
+    }                                                                          \
   } while (0)
 
 #define PADDLE_INFERSHAPE_ENFORCE_EQ(__CTX, __VAL0, __VAL1, ...) \

paddle/fluid/platform/enforce_test.cc

@@ -17,10 +17,6 @@ limitations under the License. */
 
 #include "gtest/gtest.h"
 #include "paddle/fluid/platform/enforce.h"
-#include "paddle/fluid/string/piece.h"
-
-using StringPiece = paddle::string::Piece;
-using paddle::string::HasPrefix;
 
 TEST(ENFORCE, OK) {
   PADDLE_ENFORCE(true, "Enforce is ok %d now %f", 123, 0.345);
@@ -35,8 +31,9 @@ TEST(ENFORCE, FAILED) {
     PADDLE_ENFORCE(false, "Enforce is not ok %d at all", 123);
   } catch (paddle::platform::EnforceNotMet error) {
     caught_exception = true;
-    EXPECT_TRUE(
-        HasPrefix(StringPiece(error.what()), "Enforce is not ok 123 at all"));
+    std::string ex_msg = error.what();
+    EXPECT_TRUE(ex_msg.find("Enforce is not ok 123 at all") !=
+                std::string::npos);
   }
   EXPECT_TRUE(caught_exception);
 
@@ -45,8 +42,8 @@ TEST(ENFORCE, FAILED) {
     PADDLE_ENFORCE(false, "Enforce is not ok at all");
   } catch (paddle::platform::EnforceNotMet error) {
     caught_exception = true;
-    EXPECT_TRUE(
-        HasPrefix(StringPiece(error.what()), "Enforce is not ok at all"));
+    std::string ex_msg = error.what();
+    EXPECT_TRUE(ex_msg.find("Enforce is not ok at all") != std::string::npos);
   }
   EXPECT_TRUE(caught_exception);
 
@@ -75,9 +72,9 @@ TEST(ENFORCE_EQ, NO_EXTRA_MSG_FAIL) {
     PADDLE_ENFORCE_EQ(a, 1 + 3);
   } catch (paddle::platform::EnforceNotMet error) {
     caught_exception = true;
-    HasPrefix(
-        StringPiece(error.what()),
-        "Enforce failed. Expected a == 1 + 3, but received a:2 != 1 + 3:4.");
+    std::string ex_msg = error.what();
+    EXPECT_TRUE(ex_msg.find("Expected a == 1 + 3, but received a:2 != 1 "
+                            "+ 3:4.") != std::string::npos);
   }
   EXPECT_TRUE(caught_exception);
 }
@@ -89,9 +86,9 @@ TEST(ENFORCE_EQ, EXTRA_MSG_FAIL) {
     PADDLE_ENFORCE_EQ(a, 1 + 3, "%s size not match", "their");
   } catch (paddle::platform::EnforceNotMet error) {
     caught_exception = true;
-    HasPrefix(StringPiece(error.what()),
-              "Enforce failed. Expected a == 1 + 3, but received a:2 != 1 + "
-              "3:4.\ntheir size not match");
+    std::string ex_msg = error.what();
+    EXPECT_TRUE(ex_msg.find("Expected a == 1 + 3, but received a:2 != 1 + "
+                            "3:4.\ntheir size not match") != std::string::npos);
   }
   EXPECT_TRUE(caught_exception);
 }
@@ -108,10 +105,9 @@ TEST(ENFORCE_NE, FAIL) {
     PADDLE_ENFORCE_NE(1.0, 1UL);
   } catch (paddle::platform::EnforceNotMet error) {
     caught_exception = true;
-    EXPECT_TRUE(HasPrefix(
-        StringPiece(error.what()),
-        "Enforce failed. Expected 1.0 != 1UL, but received 1.0:1 == 1UL:1."))
-        << error.what() << " does not have expected prefix";
+    std::string ex_msg = error.what();
+    EXPECT_TRUE(ex_msg.find("Expected 1.0 != 1UL, but "
+                            "received 1.0:1 == 1UL:1.") != std::string::npos);
   }
   EXPECT_TRUE(caught_exception);
 }
@@ -123,9 +119,9 @@ TEST(ENFORCE_GT, FAIL) {
     PADDLE_ENFORCE_GT(1, 2);
   } catch (paddle::platform::EnforceNotMet error) {
     caught_exception = true;
-    EXPECT_TRUE(
-        HasPrefix(StringPiece(error.what()),
-                  "Enforce failed. Expected 1 > 2, but received 1:1 <= 2:2."));
+    std::string ex_msg = error.what();
+    EXPECT_TRUE(ex_msg.find("Expected 1 > 2, but received 1:1 <= 2:2.") !=
+                std::string::npos);
   }
   EXPECT_TRUE(caught_exception);
 }
@@ -141,9 +137,9 @@ TEST(ENFORCE_GE, FAIL) {
     PADDLE_ENFORCE_GE(1, 2);
   } catch (paddle::platform::EnforceNotMet error) {
     caught_exception = true;
-    EXPECT_TRUE(
-        HasPrefix(StringPiece(error.what()),
-                  "Enforce failed. Expected 1 >= 2, but received 1:1 < 2:2."));
+    std::string ex_msg = error.what();
+    EXPECT_TRUE(ex_msg.find("Expected 1 >= 2, but received 1:1 < 2:2.") !=
+                std::string::npos);
   }
   EXPECT_TRUE(caught_exception);
 }
@@ -161,9 +157,9 @@ TEST(ENFORCE_LE, FAIL) {
     PADDLE_ENFORCE_GT(1, 2);
   } catch (paddle::platform::EnforceNotMet error) {
     caught_exception = true;
-    EXPECT_TRUE(
-        HasPrefix(StringPiece(error.what()),
-                  "Enforce failed. Expected 1 > 2, but received 1:1 <= 2:2."));
+    std::string ex_msg = error.what();
+    EXPECT_TRUE(ex_msg.find("Expected 1 > 2, but received 1:1 <= 2:2.") !=
+                std::string::npos);
   }
   EXPECT_TRUE(caught_exception);
 }
@@ -179,9 +175,10 @@ TEST(ENFORCE_LT, FAIL) {
     PADDLE_ENFORCE_LT(1UL, 0.12);
   } catch (paddle::platform::EnforceNotMet error) {
     caught_exception = true;
-    EXPECT_TRUE(HasPrefix(StringPiece(error.what()),
-                          "Enforce failed. Expected 1UL < 0.12, but "
-                          "received 1UL:1 >= 0.12:0.12."));
+    std::string ex_msg = error.what();
+    EXPECT_TRUE(ex_msg.find("Expected 1UL < 0.12, but "
+                            "received 1UL:1 >= 0.12:0.12.") !=
+                std::string::npos);
   }
   EXPECT_TRUE(caught_exception);
 }
@@ -198,7 +195,8 @@ TEST(ENFORCE_NOT_NULL, FAIL) {
     PADDLE_ENFORCE_NOT_NULL(a);
   } catch (paddle::platform::EnforceNotMet error) {
     caught_exception = true;
-    EXPECT_TRUE(HasPrefix(StringPiece(error.what()), "a should not be null"));
+    std::string ex_msg = error.what();
+    EXPECT_TRUE(ex_msg.find("a should not be null") != std::string::npos);
   }
   EXPECT_TRUE(caught_exception);
 }
@@ -251,7 +249,8 @@ TEST(EOF_EXCEPTION, THROW_EOF) {
     PADDLE_THROW_EOF();
   } catch (paddle::platform::EOFException error) {
     caught_eof = true;
-    EXPECT_TRUE(HasPrefix(StringPiece(error.what()), "There is no next data."));
+    std::string ex_msg = error.what();
+    EXPECT_TRUE(ex_msg.find("There is no next data.") != std::string::npos);
   }
   EXPECT_TRUE(caught_eof);
 }

python/paddle/fluid/executor.py

@@ -712,7 +712,8 @@ class Executor(object):
                 use_program_cache=use_program_cache)
         except Exception as e:
             if not isinstance(e, core.EOFException):
-                print("!!!A non-EOF exception is thrown.")
+                warnings.warn(
+                    "The following exception is not an EOF exception.")
             six.reraise(*sys.exc_info())
 
     def _run_impl(self, program, feed, fetch_list, feed_var_name,