From 193c08adfe0d46a5ef5a5cf38cc12bc40ea62143 Mon Sep 17 00:00:00 2001 From: Clemens Backes Date: Wed, 8 Jan 2020 19:45:54 +0100 Subject: [PATCH] [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/+/1991866 Reviewed-by: Michael Lippautz Commit-Queue: Clemens Backes Cr-Commit-Position: refs/heads/master@{#65705} --- src/base/logging.cc | 38 ++++++------- src/base/logging.h | 65 ++++++++++++---------- test/unittests/base/logging-unittest.cc | 71 ++++++++++++++++++------- 3 files changed, 107 insertions(+), 67 deletions(-) diff --git a/src/base/logging.cc b/src/base/logging.cc index 73da832fae..9e1cf59f64 100644 --- a/src/base/logging.cc +++ b/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(ch); - os.flags(flags); + oss << std::hex << "\\x" << static_cast(ch); } } + return oss.str(); } void DefaultDcheckHandler(const char* file, int line, const char* message) { @@ -73,18 +73,18 @@ void SetDcheckFunction(void (*dcheck_function)(const char*, int, const char*)) { // Define specialization to pretty print characters (escaping non-printable // characters) and to print c strings as pointers instead of strings. -#define DEFINE_PRINT_CHECK_OPERAND_CHAR(type) \ - template <> \ - void PrintCheckOperand(std::ostream & os, type ch) { \ - PrettyPrintChar(os, ch); \ - } \ - template <> \ - void PrintCheckOperand(std::ostream & os, type * cstr) { \ - os << static_cast(cstr); \ - } \ - template <> \ - void PrintCheckOperand(std::ostream & os, const type* cstr) { \ - os << static_cast(cstr); \ +#define DEFINE_PRINT_CHECK_OPERAND_CHAR(type) \ + template <> \ + std::string PrintCheckOperand(type ch) { \ + return PrettyPrintChar(ch); \ + } \ + template <> \ + std::string PrintCheckOperand(type * cstr) { \ + return PrintCheckOperand(cstr); \ + } \ + template <> \ + std::string PrintCheckOperand(const type* cstr) { \ + return PrintCheckOperand(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, \ char const*); \ - template void PrintCheckOperand(std::ostream&, type); + template std::string PrintCheckOperand(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) diff --git a/src/base/logging.h b/src/base/logging.h index 1ae8a076ea..790018c98e 100644 --- a/src/base/logging.h +++ b/src/base/logging.h @@ -138,9 +138,12 @@ V8_BASE_EXPORT void SetDcheckFunction(void (*dcheck_Function)(const char*, int, template typename std::enable_if< !std::is_function::type>::value && - has_output_operator::value>::type -PrintCheckOperand(std::ostream& os, T val) { - os << std::forward(val); + has_output_operator::value, + std::string>::type +PrintCheckOperand(T val) { + std::ostringstream oss; + oss << std::forward(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 std::enable_if< - std::is_function::type>::value>::type -PrintCheckOperand(std::ostream& os, T val) { - os << reinterpret_cast(val); + std::is_function::type>::value, + std::string>::type +PrintCheckOperand(T val) { + return PrintCheckOperand(reinterpret_cast(val)); } // Define PrintCheckOperand for enums which have no operator<<. template -typename std::enable_if::value && - !has_output_operator::value>::type -PrintCheckOperand(std::ostream& os, T val) { +typename std::enable_if< + std::is_enum::value && !has_output_operator::value, std::string>::type +PrintCheckOperand(T val) { using underlying_t = typename std::underlying_type::type; // 8-bit types are not printed as number, so extend them to 16 bit. using int_t = typename std::conditional< std::is_same::value, uint16_t, typename std::conditional::value, int16_t, underlying_t>::type>::type; - PrintCheckOperand(os, static_cast(static_cast(val))); + return PrintCheckOperand(static_cast(static_cast(val))); } // Define default PrintCheckOperand for non-printable types. template typename std::enable_if::value && - !std::is_enum::value>::type -PrintCheckOperand(std::ostream& os, T val) { - os << ""; + !std::is_enum::value, + std::string>::type +PrintCheckOperand(T val) { + return ""; } // Define specializations for character types, defined in logging.cc. -#define DEFINE_PRINT_CHECK_OPERAND_CHAR(type) \ - template <> \ - V8_BASE_EXPORT void PrintCheckOperand(std::ostream & os, type ch); \ - template <> \ - V8_BASE_EXPORT void PrintCheckOperand(std::ostream & os, \ - type * cstr); \ - template <> \ - V8_BASE_EXPORT void PrintCheckOperand(std::ostream & os, \ - const type* cstr); +#define DEFINE_PRINT_CHECK_OPERAND_CHAR(type) \ + template <> \ + V8_BASE_EXPORT std::string PrintCheckOperand(type ch); \ + template <> \ + V8_BASE_EXPORT std::string PrintCheckOperand(type * cstr); \ + template <> \ + V8_BASE_EXPORT std::string PrintCheckOperand(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 V8_NOINLINE std::string* MakeCheckOpString(Lhs lhs, Rhs rhs, char const* msg) { + std::string lhs_str = PrintCheckOperand(lhs); + std::string rhs_str = PrintCheckOperand(rhs); std::ostringstream ss; - ss << msg << " ("; - PrintCheckOperand(ss, lhs); - ss << " vs. "; - PrintCheckOperand(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, char const*); \ - extern template V8_BASE_EXPORT void PrintCheckOperand(std::ostream&, \ - type); + extern template V8_BASE_EXPORT std::string PrintCheckOperand(type); EXPLICIT_CHECK_OP_INSTANTIATION(int) EXPLICIT_CHECK_OP_INSTANTIATION(long) // NOLINT(runtime/int) diff --git a/test/unittests/base/logging-unittest.cc b/test/unittests/base/logging-unittest.cc index 762d6762cd..157d84bac1 100644 --- a/test/unittests/base/logging-unittest.cc +++ b/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{}", - " vs. ")); + "", "")); 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) {