[base] Improve logging for long error messages

When comparing objects which get printed to very long strings (e.g.
collections like vectors), it's much more readable if they get printed
to individual lines. Differences are much easier to spot then.

This CL refactors the CHECK/DCHECK macros to print the left hand side
and right-hand side in individual lines if any of them is longer than 50
characters.

To that end, the {PrintCheckOperand} method (only used from
{MakeCheckOpString}) is changed to return the string directly instead of
printing to an output stream.

R=mlippautz@chromium.org

Change-Id: I6e24a5cbfeb1af53fa0aca2828e23f642b15569c
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/1991866Reviewed-by: Michael Lippautz <mlippautz@chromium.org>
Commit-Queue: Clemens Backes <clemensb@chromium.org>
Cr-Commit-Position: refs/heads/master@{#65705}

src/base/logging.cc

@@ -23,11 +23,12 @@ void (*g_print_stack_trace)() = nullptr;
 
 void (*g_dcheck_function)(const char*, int, const char*) = DefaultDcheckHandler;
 
-void PrettyPrintChar(std::ostream& os, int ch) {
+std::string PrettyPrintChar(int ch) {
+  std::ostringstream oss;
   switch (ch) {
 #define CHAR_PRINT_CASE(ch) \
   case ch:                  \
-    os << #ch;              \
+    oss << #ch;             \
     break;
 
     CHAR_PRINT_CASE('\0')
@@ -43,13 +44,12 @@ void PrettyPrintChar(std::ostream& os, int ch) {
 #undef CHAR_PRINT_CASE
     default:
       if (std::isprint(ch)) {
-        os << '\'' << ch << '\'';
+        oss << '\'' << ch << '\'';
       } else {
-        auto flags = os.flags(std::ios_base::hex);
-        os << "\\x" << static_cast<unsigned int>(ch);
-        os.flags(flags);
+        oss << std::hex << "\\x" << static_cast<unsigned int>(ch);
       }
   }
+  return oss.str();
 }
 
 void DefaultDcheckHandler(const char* file, int line, const char* message) {
@@ -75,16 +75,16 @@ void SetDcheckFunction(void (*dcheck_function)(const char*, int, const char*)) {
 // characters) and to print c strings as pointers instead of strings.
 #define DEFINE_PRINT_CHECK_OPERAND_CHAR(type)                    \
   template <>                                                    \
-  void PrintCheckOperand<type>(std::ostream & os, type ch) {                 \
-    PrettyPrintChar(os, ch);                                                 \
+  std::string PrintCheckOperand<type>(type ch) {                 \
+    return PrettyPrintChar(ch);                                  \
   }                                                              \
   template <>                                                    \
-  void PrintCheckOperand<type*>(std::ostream & os, type * cstr) {            \
-    os << static_cast<void*>(cstr);                                          \
+  std::string PrintCheckOperand<type*>(type * cstr) {            \
+    return PrintCheckOperand<void*>(cstr);                       \
   }                                                              \
   template <>                                                    \
-  void PrintCheckOperand<const type*>(std::ostream & os, const type* cstr) { \
-    os << static_cast<const void*>(cstr);                                    \
+  std::string PrintCheckOperand<const type*>(const type* cstr) { \
+    return PrintCheckOperand<const void*>(cstr);                 \
   }
 
 DEFINE_PRINT_CHECK_OPERAND_CHAR(char)
@@ -96,7 +96,7 @@ DEFINE_PRINT_CHECK_OPERAND_CHAR(unsigned char)
 #define DEFINE_MAKE_CHECK_OP_STRING(type)                           \
   template std::string* MakeCheckOpString<type, type>(type, type,   \
                                                       char const*); \
-  template void PrintCheckOperand<type>(std::ostream&, type);
+  template std::string PrintCheckOperand<type>(type);
 DEFINE_MAKE_CHECK_OP_STRING(int)
 DEFINE_MAKE_CHECK_OP_STRING(long)       // NOLINT(runtime/int)
 DEFINE_MAKE_CHECK_OP_STRING(long long)  // NOLINT(runtime/int)

src/base/logging.h

@@ -138,9 +138,12 @@ V8_BASE_EXPORT void SetDcheckFunction(void (*dcheck_Function)(const char*, int,
 template <typename T>
 typename std::enable_if<
     !std::is_function<typename std::remove_pointer<T>::type>::value &&
-    has_output_operator<T>::value>::type
-PrintCheckOperand(std::ostream& os, T val) {
-  os << std::forward<T>(val);
+        has_output_operator<T>::value,
+    std::string>::type
+PrintCheckOperand(T val) {
+  std::ostringstream oss;
+  oss << std::forward<T>(val);
+  return oss.str();
 }
 
 // Provide an overload for functions and function pointers. Function pointers
@@ -150,43 +153,43 @@ PrintCheckOperand(std::ostream& os, T val) {
 // pointers, so this is a no-op for MSVC.)
 template <typename T>
 typename std::enable_if<
-    std::is_function<typename std::remove_pointer<T>::type>::value>::type
-PrintCheckOperand(std::ostream& os, T val) {
-  os << reinterpret_cast<const void*>(val);
+    std::is_function<typename std::remove_pointer<T>::type>::value,
+    std::string>::type
+PrintCheckOperand(T val) {
+  return PrintCheckOperand(reinterpret_cast<const void*>(val));
 }
 
 // Define PrintCheckOperand<T> for enums which have no operator<<.
 template <typename T>
-typename std::enable_if<std::is_enum<T>::value &&
-                        !has_output_operator<T>::value>::type
-PrintCheckOperand(std::ostream& os, T val) {
+typename std::enable_if<
+    std::is_enum<T>::value && !has_output_operator<T>::value, std::string>::type
+PrintCheckOperand(T val) {
   using underlying_t = typename std::underlying_type<T>::type;
   // 8-bit types are not printed as number, so extend them to 16 bit.
   using int_t = typename std::conditional<
       std::is_same<underlying_t, uint8_t>::value, uint16_t,
       typename std::conditional<std::is_same<underlying_t, int8_t>::value,
                                 int16_t, underlying_t>::type>::type;
-  PrintCheckOperand(os, static_cast<int_t>(static_cast<underlying_t>(val)));
+  return PrintCheckOperand(static_cast<int_t>(static_cast<underlying_t>(val)));
 }
 
 // Define default PrintCheckOperand<T> for non-printable types.
 template <typename T>
 typename std::enable_if<!has_output_operator<T>::value &&
-                        !std::is_enum<T>::value>::type
-PrintCheckOperand(std::ostream& os, T val) {
-  os << "<unprintable>";
+                            !std::is_enum<T>::value,
+                        std::string>::type
+PrintCheckOperand(T val) {
+  return "<unprintable>";
 }
 
 // Define specializations for character types, defined in logging.cc.
 #define DEFINE_PRINT_CHECK_OPERAND_CHAR(type)                       \
   template <>                                                       \
-  V8_BASE_EXPORT void PrintCheckOperand<type>(std::ostream & os, type ch); \
+  V8_BASE_EXPORT std::string PrintCheckOperand<type>(type ch);      \
   template <>                                                       \
-  V8_BASE_EXPORT void PrintCheckOperand<type*>(std::ostream & os,          \
-                                               type * cstr);               \
+  V8_BASE_EXPORT std::string PrintCheckOperand<type*>(type * cstr); \
   template <>                                                       \
-  V8_BASE_EXPORT void PrintCheckOperand<const type*>(std::ostream & os,    \
-                                                     const type* cstr);
+  V8_BASE_EXPORT std::string PrintCheckOperand<const type*>(const type* cstr);
 
 DEFINE_PRINT_CHECK_OPERAND_CHAR(char)
 DEFINE_PRINT_CHECK_OPERAND_CHAR(signed char)
@@ -199,12 +202,17 @@ DEFINE_PRINT_CHECK_OPERAND_CHAR(unsigned char)
 // takes ownership of the returned string.
 template <typename Lhs, typename Rhs>
 V8_NOINLINE std::string* MakeCheckOpString(Lhs lhs, Rhs rhs, char const* msg) {
+  std::string lhs_str = PrintCheckOperand<Lhs>(lhs);
+  std::string rhs_str = PrintCheckOperand<Rhs>(rhs);
   std::ostringstream ss;
-  ss << msg << " (";
-  PrintCheckOperand<Lhs>(ss, lhs);
-  ss << " vs. ";
-  PrintCheckOperand<Rhs>(ss, rhs);
-  ss << ")";
+  ss << msg;
+  constexpr size_t kMaxInlineLength = 50;
+  if (lhs_str.size() <= kMaxInlineLength &&
+      rhs_str.size() <= kMaxInlineLength) {
+    ss << " (" << lhs_str << " vs. " << rhs_str << ")";
+  } else {
+    ss << "\n   " << lhs_str << "\n vs.\n   " << rhs_str << "\n";
+  }
   return new std::string(ss.str());
 }
 
@@ -213,8 +221,7 @@ V8_NOINLINE std::string* MakeCheckOpString(Lhs lhs, Rhs rhs, char const* msg) {
 #define EXPLICIT_CHECK_OP_INSTANTIATION(type)                                \
   extern template V8_BASE_EXPORT std::string* MakeCheckOpString<type, type>( \
       type, type, char const*);                                              \
-  extern template V8_BASE_EXPORT void PrintCheckOperand<type>(std::ostream&, \
-                                                              type);
+  extern template V8_BASE_EXPORT std::string PrintCheckOperand<type>(type);
 
 EXPLICIT_CHECK_OP_INSTANTIATION(int)
 EXPLICIT_CHECK_OP_INSTANTIATION(long)       // NOLINT(runtime/int)

test/unittests/base/logging-unittest.cc

@@ -74,19 +74,32 @@ TEST(LoggingTest, CompareAgainstStaticConstPointer) {
   DCHECK_##name(lhs, rhs)
 
 namespace {
-std::string FailureMessage(const char* msg, const char* debug_msg) {
-  std::string regexp(msg);
-#ifdef DEBUG
-  regexp.append(" (").append(debug_msg).append(")");
-#endif
+std::string SanitizeRegexp(std::string msg) {
   size_t last_pos = 0;
   do {
-    size_t pos = regexp.find_first_of("(){}+*", last_pos);
+    size_t pos = msg.find_first_of("(){}+*", last_pos);
     if (pos == std::string::npos) break;
-    regexp.insert(pos, "\\");
+    msg.insert(pos, "\\");
     last_pos = pos + 2;
   } while (true);
-  return regexp;
+  return msg;
+}
+
+std::string FailureMessage(const char* msg, const char* lhs, const char* rhs) {
+  std::string full_msg(msg);
+#ifdef DEBUG
+  full_msg.append(" (").append(lhs).append(" vs. ").append(rhs);
+#endif
+  return SanitizeRegexp(std::move(full_msg));
+}
+
+std::string LongFailureMessage(const char* msg, const char* lhs,
+                               const char* rhs) {
+  std::string full_msg(msg);
+#ifdef DEBUG
+  full_msg.append("\n   ").append(lhs).append("\n vs.\n   ").append(rhs);
+#endif
+  return SanitizeRegexp(std::move(full_msg));
 }
 }  // namespace
 
@@ -107,7 +120,7 @@ TEST(LoggingTest, CompareWithDifferentSignedness) {
   // Check that the values are output correctly on error.
   ASSERT_DEATH_IF_SUPPORTED(
       ([&] { CHECK_GT(i32, u64); })(),
-      FailureMessage("Check failed: i32 > u64", "10 vs. 40"));
+      FailureMessage("Check failed: i32 > u64", "10", "40"));
 }
 
 TEST(LoggingTest, CompareWithReferenceType) {
@@ -125,7 +138,7 @@ TEST(LoggingTest, CompareWithReferenceType) {
   // Check that the values are output correctly on error.
   ASSERT_DEATH_IF_SUPPORTED(
       ([&] { CHECK_GT(*&i32, u64); })(),
-      FailureMessage("Check failed: *&i32 > u64", "10 vs. 40"));
+      FailureMessage("Check failed: *&i32 > u64", "10", "40"));
 }
 
 enum TestEnum1 { ONE, TWO };
@@ -172,27 +185,27 @@ TEST(LoggingTest, CompareClassTypes) {
   ASSERT_DEATH_IF_SUPPORTED(
       ([&] { CHECK_NE(TestClass1{}, TestClass1{}); })(),
       FailureMessage("Check failed: TestClass1{} != TestClass1{}",
-                     "<unprintable> vs. <unprintable>"));
+                     "<unprintable>", "<unprintable>"));
   ASSERT_DEATH_IF_SUPPORTED(
       ([&] { CHECK_LT(TestClass2{4}, TestClass2{3}); })(),
       FailureMessage("Check failed: TestClass2{4} < TestClass2{3}",
-                     "TestClass2(4) vs. TestClass2(3)"));
+                     "TestClass2(4)", "TestClass2(3)"));
 }
 
 TEST(LoggingDeathTest, OutputEnumValues) {
   ASSERT_DEATH_IF_SUPPORTED(
       ([&] { CHECK_EQ(ONE, TWO); })(),
-      FailureMessage("Check failed: ONE == TWO", "0 vs. 1"));
+      FailureMessage("Check failed: ONE == TWO", "0", "1"));
   ASSERT_DEATH_IF_SUPPORTED(
       ([&] { CHECK_NE(BAR, 2 + 3); })(),
-      FailureMessage("Check failed: BAR != 2 + 3", "5 vs. 5"));
+      FailureMessage("Check failed: BAR != 2 + 3", "5", "5"));
   ASSERT_DEATH_IF_SUPPORTED(
       ([&] { CHECK_EQ(TestEnum3::A, TestEnum3::B); })(),
-      FailureMessage("Check failed: TestEnum3::A == TestEnum3::B", "0 vs. 1"));
+      FailureMessage("Check failed: TestEnum3::A == TestEnum3::B", "0", "1"));
   ASSERT_DEATH_IF_SUPPORTED(
       ([&] { CHECK_GE(TestEnum4::FIRST, TestEnum4::SECOND); })(),
-      FailureMessage("Check failed: TestEnum4::FIRST >= TestEnum4::SECOND",
-                     "0 vs. 1"));
+      FailureMessage("Check failed: TestEnum4::FIRST >= TestEnum4::SECOND", "0",
+                     "1"));
 }
 
 enum TestEnum5 { TEST_A, TEST_B };
@@ -207,11 +220,31 @@ void operator<<(std::ostream& str, TestEnum6 val) {
 TEST(LoggingDeathTest, OutputEnumWithOutputOperator) {
   ASSERT_DEATH_IF_SUPPORTED(
       ([&] { CHECK_EQ(TEST_A, TEST_B); })(),
-      FailureMessage("Check failed: TEST_A == TEST_B", "A vs. B"));
+      FailureMessage("Check failed: TEST_A == TEST_B", "A", "B"));
   ASSERT_DEATH_IF_SUPPORTED(
       ([&] { CHECK_GE(TestEnum6::TEST_C, TestEnum6::TEST_D); })(),
       FailureMessage("Check failed: TestEnum6::TEST_C >= TestEnum6::TEST_D",
-                     "C vs. D"));
+                     "C", "D"));
+}
+
+TEST(LoggingDeathTest, OutputLongValues) {
+  constexpr size_t kMaxInlineLength = 50;  // see logging.h
+  std::string str1;
+  while (str1.length() < kMaxInlineLength) {
+    str1.push_back('a' + (str1.length() % 26));
+  }
+  std::string str2("abc");
+  ASSERT_DEATH_IF_SUPPORTED(
+      ([&] { CHECK_EQ(str1, str2); })(),
+      FailureMessage("Check failed: str1 == str2",
+                     "abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwx",
+                     "abc"));
+  str1.push_back('X');
+  ASSERT_DEATH_IF_SUPPORTED(
+      ([&] { CHECK_EQ(str1, str2); })(),
+      LongFailureMessage("Check failed: str1 == str2",
+                         "abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxX",
+                         "abc"));
 }
 
 TEST(LoggingDeathTest, FatalKills) {