!35633 Error message structure optimization, hierarchical printing

Merge pull request !35633 from wangjunbao/master

.jenkins/check/config/filter_cpplint.txt

@@ -16,6 +16,7 @@
 "mindspore/mindspore/ccsrc/plugin/device/cpu/kernel/nnacl/"                                        "readability/casting"
 "mindspore/mindspore/ccsrc/plugin/device/gpu/hal/device/gpu_kernel_runtime.cc"                     "build/include_what_you_use"
 "mindspore/mindspore/ccsrc/utils/convert_utils_py.cc"                                              "whitespace/indent"
+"mindspore/mindspore/core/utils/log_adapter.cc"                                                    "runtime/references"
 
 # Modelzoo
 "mindspore/model_zoo/official/cv/yolov4_tiny/infer/mxbase/src/Yolov4TinyDetection.h"                 "runtime/references"

mindspore/ccsrc/pipeline/jit/debug/trace.cc

@@ -475,7 +475,22 @@ void ClearTraceStack() {
   cnode_debug_stack.clear();
 }
 
-void GetTraceStackInfo(std::ostringstream &oss) {
+void PrintMessage(std::ostringstream &oss, const std::string &content, bool add_title) {
+  if (add_title) {
+    const std::string &message = oss.str();
+    size_t length = message.length();
+    if ((length != 0) && (message[length - 1] != '\n')) {
+      oss << "\n";
+    }
+
+    oss << "\n----------------------------------------------------\n"
+        << "- The Traceback of Net Construct Code:"
+        << "\n----------------------------------------------------";
+  }
+  oss << content;
+}
+
+void GetTraceStackInfo(std::ostringstream &oss, bool add_title) {
   TraceGraphEval();
   std::ostringstream trace_info;
   GetEvalStackInfo(trace_info);
@@ -484,11 +499,13 @@ void GetTraceStackInfo(std::ostringstream &oss) {
     if (debug_info != nullptr && TraceManager::record_debug_info_flag() == true) {
       auto debug_str = trace::GetDebugInfo(debug_info);
       if (!debug_str.empty()) {
-        oss << "\n\n# " << debug_str;
+        std::ostringstream content;
+        content << "\n\n# " << debug_str;
+        PrintMessage(oss, content.str(), add_title);
       }
     }
   } else {
-    oss << trace_info.str();
+    PrintMessage(oss, trace_info.str(), add_title);
   }
 }
 

mindspore/ccsrc/pipeline/jit/debug/trace.h

@@ -46,7 +46,7 @@ void TraceEvalCNodeEnter(const abstract::AnfNodeConfigPtr &node_cfg);
 void TraceEvalCNodeLeave();
 TraceCNodeEvalStack &GetCNodeDebugStack();
 TraceGraphEvalStack &GetCurrentGraphEvalStack();
-void GetTraceStackInfo(std::ostringstream &oss);
+void GetTraceStackInfo(std::ostringstream &oss, bool add_title = false);
 std::string GetAbstractStr(const abstract::AbstractBasePtr &abs);
 void ClearTraceStack();
 }  // namespace trace

mindspore/core/utils/log_adapter.cc

@@ -34,6 +34,7 @@
 // namespace to support utils module definition
 namespace mindspore {
 constexpr int kNameMaxLength = 18;
+constexpr size_t kStep = 2;
 #if defined(__ANDROID__) || defined(ANDROID)
 constexpr const char *ANDROID_LOG_TAG = "MS_LITE";
 #endif
@@ -179,6 +180,137 @@ void LogWriter::set_trace_provider(const TraceProvider &trace_provider) {
 
 LogWriter::TraceProvider LogWriter::trace_provider() { return trace_provider_; }
 
+static inline std::string GetEnv(const std::string &envvar) {
+  const char *value = std::getenv(envvar.c_str());
+
+  if (value == nullptr) {
+    return std::string();
+  }
+
+  return std::string(value);
+}
+
+// When GLOG_logtostderr is set to 0, logs are output to a file, then will print duplicate message
+// in exception log and stack. Otherwise when GLOG_logtostderr is set to 1, logs are output to the screen,
+// then will only print message in exception stack.
+void LogWriter::RemoveLabelBeforeOutputLog(const std::ostringstream &msg) const {
+  if (GetEnv("GLOG_logtostderr") == "0") {
+    std::string str = msg.str();
+    auto replace = [&](const std::string &orgStr, const std::string &newStr) {
+      std::string::size_type pos;
+      while ((pos = str.find(orgStr)) != std::string::npos) {
+        str.replace(pos, orgStr.length(), newStr);
+      }
+      return str;
+    };
+    // remove label "#dmsg#" and "#umsg#"
+    str = replace("#dmsg#", "");
+    str = replace("#umsg#", "");
+    std::ostringstream replaced_msg;
+    replaced_msg << str;
+    OutputLog(replaced_msg);
+  }
+}
+
+// Function to split string based on character delimiter
+void SplitString(const std::string &message, const std::string &delimiter, std::vector<std::string> *output) {
+  size_t pos1, pos2;
+  pos1 = 0;
+  pos2 = message.find(delimiter);
+  MS_EXCEPTION_IF_NULL(output);
+
+  while (pos2 != std::string::npos) {
+    (void)output->emplace_back(message.substr(pos1, pos2 - pos1));
+    pos1 = pos2 + delimiter.size();
+    pos2 = message.find(delimiter, pos1);
+  }
+
+  if (pos1 != message.length()) {
+    (void)output->emplace_back(message.substr(pos1));
+  }
+}
+
+// Parse exception message format like: Error Description#dmsg#Developer Message Title#dmsg#Developer Message Content
+// #umsg#User Message Title#umsg#User Message Content
+void ParseExceptionMessage(const std::string &message, std::ostringstream &oss, std::vector<std::string> *dmsg,
+                           std::vector<std::string> *umsg) {
+  std::vector<std::string> vec;
+  SplitString(message, "#dmsg#", &vec);  // first:split message by label #dmsg#
+
+  if (!vec.empty() && (vec[0].find("#umsg#") == std::string::npos)) {
+    oss << vec[0];
+  }
+
+  MS_EXCEPTION_IF_NULL(dmsg);
+  MS_EXCEPTION_IF_NULL(umsg);
+
+  for (size_t i = 0; i < vec.size(); i++) {
+    if (vec[i].find("#umsg#") != std::string::npos) {
+      std::vector<std::string> temp;
+      SplitString(vec[i], "#umsg#", &temp);  // second:split message by label #umsg#
+      if (!temp.empty()) {
+        if (i == 0) {
+          oss << temp[0];
+        } else {
+          (void)dmsg->emplace_back(temp[0]);
+        }
+        (void)umsg->insert(umsg->end(), temp.begin() + 1, temp.end());
+      }
+    } else {
+      if (i != 0) {
+        (void)dmsg->emplace_back(vec[i]);
+      }
+    }
+  }
+}
+
+void PrintMessage(std::ostringstream &oss, const std::string &title, const std::string &content) {
+  const std::string &message = oss.str();
+  size_t length = message.length();
+  if ((length != 0) && (message[length - 1] != '\n')) {
+    oss << "\n";
+  }
+
+  oss << "\n----------------------------------------------------\n"
+      << title << "\n----------------------------------------------------\n"
+      << content;
+}
+
+void DisplayDevExceptionMessage(std::ostringstream &oss, const std::vector<std::string> &dmsg,
+                                const LocationInfo &location) {
+  bool display = true;
+  if (GetEnv("MS_EXCEPTION_DISPLAY_LEVEL") == "1") {
+    display = false;
+  }
+
+  if (display) {
+    const std::string CPP_CALL_STACK_TITLE = "- C++ Call Stack: (For framework developers)";
+    std::ostringstream cpp_call_stack_content;
+    cpp_call_stack_content << location.file_ << ":" << location.line_ << " " << location.func_ << "\n";
+    PrintMessage(oss, CPP_CALL_STACK_TITLE, cpp_call_stack_content.str());
+
+    size_t size = dmsg.size();
+    if ((size != 0) && (size % kStep == 0)) {
+      for (size_t i = 0; i < size; i += kStep) {
+        std::ostringstream dmsg_title;
+        dmsg_title << "- " << dmsg[i] << " (For framework developers)";
+        PrintMessage(oss, dmsg_title.str(), dmsg[i + 1]);
+      }
+    }
+  }
+}
+
+void DisplayUserExceptionMessage(std::ostringstream &oss, const std::vector<std::string> &umsg) {
+  size_t size = umsg.size();
+  if ((size != 0) && (size % kStep == 0)) {
+    for (size_t i = 0; i < size; i += kStep) {
+      std::ostringstream umsg_title;
+      umsg_title << "- " << umsg[i];
+      PrintMessage(oss, umsg_title.str(), umsg[i + 1]);
+    }
+  }
+}
+
 void LogWriter::OutputLog(const std::ostringstream &msg) const {
 #ifdef USE_GLOG
 #define google mindspore_private
@@ -219,21 +351,26 @@ void LogWriter::operator^(const LogStream &stream) const {
   std::ostringstream msg;
   msg << stream.sstream_->rdbuf();
   std::ostringstream oss;
-  oss << location_.file_ << ":" << location_.line_ << " " << location_.func_ << "] ";
+  std::vector<std::string> dmsg;
-  oss << msg.str();
+  std::vector<std::string> umsg;
+
+  ParseExceptionMessage(msg.str(), oss, &dmsg, &umsg);
+  DisplayUserExceptionMessage(oss, umsg);
 
   thread_local bool running = false;
   if (!running) {
     running = true;
     if (this_thread_max_log_level >= EXCEPTION) {
-      OutputLog(msg);
+      RemoveLabelBeforeOutputLog(msg);
     }
     if (trace_provider_ != nullptr) {
-      trace_provider_(oss);
+      trace_provider_(oss, true);
     }
     running = false;
   }
 
+  DisplayDevExceptionMessage(oss, dmsg, location_);
+
   if (exception_handler_ != nullptr) {
     exception_handler_(exception_type_, oss.str());
   }
@@ -241,16 +378,6 @@ void LogWriter::operator^(const LogStream &stream) const {
 }
 #endif
 
-static inline std::string GetEnv(const std::string &envvar) {
-  const char *value = std::getenv(envvar.c_str());
-
-  if (value == nullptr) {
-    return std::string();
-  }
-
-  return std::string(value);
-}
-
 enum class LogConfigToken : size_t {
   INVALID,      // indicate invalid token
   LEFT_BRACE,   // '{'

mindspore/core/utils/log_adapter.h

@@ -247,7 +247,7 @@ class TryCatchGuard {
 class MS_CORE_API LogWriter {
  public:
   using ExceptionHandler = void (*)(ExceptionType, const std::string &);
-  using TraceProvider = std::function<void(std::ostringstream &oss)>;
+  using TraceProvider = std::function<void(std::ostringstream &oss, bool add_title)>;
 
   LogWriter(const LocationInfo &location, MsLogLevel log_level, SubModuleId submodule,
             ExceptionType excp_type = NoExceptionType)
@@ -272,6 +272,7 @@ class MS_CORE_API LogWriter {
 
  private:
   void OutputLog(const std::ostringstream &msg) const;
+  void RemoveLabelBeforeOutputLog(const std::ostringstream &msg) const;
 
   LocationInfo location_;
   MsLogLevel log_level_;

tests/ut/cpp/utils/log_adapter_test.cc

@@ -0,0 +1,61 @@
+/**
+ * Copyright 2022 Huawei Technologies Co., Ltd
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include "common/common_test.h"
+#include "utils/log_adapter.h"
+
+namespace {
+constexpr char kMsExceptionDisplayLevel[] = "MS_EXCEPTION_DISPLAY_LEVEL";
+}  // namespace
+
+namespace mindspore {
+class TestLogAdapter : public UT::Common {
+ public:
+  TestLogAdapter() {}
+
+  void TearDown() override { (void)unsetenv(kMsExceptionDisplayLevel); }
+};
+
+/// Feature: Error message structure optimization, hierarchical printing
+/// Description: set MS_EXCEPTION_DISPLAY_LEVEL to 0 and run pass
+/// Expectation: dmsg and umsg both display
+TEST_F(TestLogAdapter, TestParseExceptionMessage1) {
+  (void)setenv(kMsExceptionDisplayLevel, "0", 1);
+  try {
+    MS_LOG(EXCEPTION) << "Exception Description#dmsg#The Dev Title1:#dmsg#The Dev Content1"
+                      << "#umsg#The User Title1:#umsg#The User Content1";
+  } catch (const std::exception &ex) {
+    const std::string &exception_str = ex.what();
+    MS_LOG(INFO) << exception_str;
+    ASSERT_TRUE(exception_str.find("- C++ Call Stack: (For framework developers)") != std::string::npos);
+  }
+}
+
+/// Feature: Error message structure optimization, hierarchical printing
+/// Description: set MS_EXCEPTION_DISPLAY_LEVEL to 1 and run pass
+/// Expectation: only umsg displays
+TEST_F(TestLogAdapter, TestParseExceptionMessage2) {
+  (void)setenv(kMsExceptionDisplayLevel, "1", 1);
+  try {
+    MS_EXCEPTION(TypeError) << "Exception Description#dmsg#The Dev Title1:#dmsg#The Dev Content1"
+                            << "#umsg#The User Title1:#umsg#The User Content1";
+  } catch (const std::exception &ex) {
+    const std::string &exception_str = ex.what();
+    MS_LOG(INFO) << exception_str;
+    ASSERT_TRUE(exception_str.find("The Dev Content1") == std::string::npos);
+  }
+}
+}  // namespace mindspore