Skip to content

Commit

Permalink
base: preferentially keep fatal messages in truncated snippets.
Browse files Browse the repository at this point in the history 
Preferentially retain fatal log messages in snippets, so that
there is a higher likelihood they can be extracted in result_adapter
to populate ResultDB failure reasons.

Although it may be ideal to do full extraction of fatal messages here,
adding a dependency to a regular expression library seems excessive.

BUG=1238265
TEST=unit tests

Change-Id: I8b4aa31fcd52b0617b787fd14bb2fb7c257d81ac
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/3090052
Reviewed-by: Daniel Cheng <dcheng@chromium.org>
Commit-Queue: Patrick Meiring <meiring@google.com>
Cr-Commit-Position: refs/heads/main@{#913641}
  • Loading branch information
@patrickmeiring
patrickmeiring authored and Chromium LUCI CQ committed Aug 20, 2021
1 parent 892a0eb commit 078ced9
Show file tree
Hide file tree
Showing 3 changed files with 288 additions and 7 deletions.
88 changes: 81 additions & 7 deletions base/test/launcher/test_launcher.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -36,6 +36,7 @@
#include "base/run_loop.h"
#include "base/single_thread_task_runner.h"
#include "base/strings/pattern.h"
#include "base/strings/strcat.h"
#include "base/strings/string_number_conversions.h"
#include "base/strings/string_piece.h"
#include "base/strings/string_split.h"
Expand Down Expand Up @@ -793,6 +794,26 @@ int CountItemsInDirectory(const FilePath& dir) {
return items;
}

// Truncates a snippet in the middle to the given byte limit. byte_limit should
// be at least 30.
std::string TruncateSnippet(const base::StringPiece snippet,
size_t byte_limit) {
if (snippet.length() <= byte_limit) {
return std::string(snippet);
}
std::string truncation_message =
StringPrintf("\n<truncated (%zu bytes)>\n", snippet.length());
if (truncation_message.length() > byte_limit) {
// Fail gracefully.
return truncation_message;
}
size_t remaining_limit = byte_limit - truncation_message.length();
size_t first_half = remaining_limit / 2;
return base::StrCat(
{snippet.substr(0, first_half), truncation_message,
snippet.substr(snippet.length() - (remaining_limit - first_half))});
}

} // namespace

const char kGTestBreakOnFailure[] = "gtest_break_on_failure";
Expand Down Expand Up @@ -1146,14 +1167,8 @@ void TestLauncher::OnTestFinished(const TestResult& original_result) {
if (result.status == TestResult::TEST_SUCCESS)
result.status = TestResult::TEST_EXCESSIVE_OUTPUT;

// Keep the top and bottom of the log and truncate the middle part.
result.output_snippet =
result.output_snippet.substr(0, kOutputSnippetBytesLimit / 2) + "\n" +
StringPrintf("<truncated (%zu bytes)>\n",
result.output_snippet.length()) +
result.output_snippet.substr(result.output_snippet.length() -
kOutputSnippetBytesLimit / 2) +
"\n";
TruncateSnippetFocused(result.output_snippet, kOutputSnippetBytesLimit);
}

bool print_snippet = false;
Expand Down Expand Up @@ -2063,4 +2078,63 @@ std::string GetTestOutputSnippet(const TestResult& result,
return snippet;
}

std::string TruncateSnippetFocused(const base::StringPiece snippet,
size_t byte_limit) {
// Find the start of anything that looks like a fatal log message.
// We want to preferentially preserve these from truncation as we
// run extraction of fatal test errors from snippets in result_adapter
// to populate failure reasons in ResultDB. It is also convenient for
// the user to see them.
// Refer to LogMessage::Init in base/logging[_platform].cc for patterns.
size_t fatal_message_pos =
std::min(snippet.find("FATAL:"), snippet.find("FATAL "));

size_t fatal_message_start = 0;
size_t fatal_message_end = 0;
if (fatal_message_pos != std::string::npos) {
// Find the line-endings before and after the fatal message.
size_t start_pos = snippet.rfind("\n", fatal_message_pos);
if (start_pos != std::string::npos) {
fatal_message_start = start_pos;
}
size_t end_pos = snippet.find("\n", fatal_message_pos);
if (end_pos != std::string::npos) {
// Include the new-line character.
fatal_message_end = end_pos + 1;
} else {
fatal_message_end = snippet.length();
}
}
// Limit fatal message length to half the snippet byte quota. This ensures
// we have space for some context at the beginning and end of the snippet.
fatal_message_end =
std::min(fatal_message_end, fatal_message_start + (byte_limit / 2));

// Distribute remaining bytes between start and end of snippet.
// The split is either even, or if one is small enough to be displayed
// without truncation, it gets displayed in full and the other split gets
// the remaining bytes.
size_t remaining_bytes =
byte_limit - (fatal_message_end - fatal_message_start);
size_t start_split_bytes;
size_t end_split_bytes;
if (fatal_message_start < remaining_bytes / 2) {
start_split_bytes = fatal_message_start;
end_split_bytes = remaining_bytes - fatal_message_start;
} else if ((snippet.length() - fatal_message_end) < remaining_bytes / 2) {
start_split_bytes =
remaining_bytes - (snippet.length() - fatal_message_end);
end_split_bytes = (snippet.length() - fatal_message_end);
} else {
start_split_bytes = remaining_bytes / 2;
end_split_bytes = remaining_bytes - start_split_bytes;
}
return base::StrCat(
{TruncateSnippet(snippet.substr(0, fatal_message_start),
start_split_bytes),
snippet.substr(fatal_message_start,
fatal_message_end - fatal_message_start),
TruncateSnippet(snippet.substr(fatal_message_end), end_split_bytes)});
}

} // namespace base
5 changes: 5 additions & 0 deletions base/test/launcher/test_launcher.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -332,6 +332,11 @@ size_t NumParallelJobs(unsigned int cores_per_job);
std::string GetTestOutputSnippet(const TestResult& result,
const std::string& full_output);

// Truncates a snippet to approximately the allowed length, while trying to
// retain fatal messages. Exposed for testing only.
std::string TruncateSnippetFocused(const base::StringPiece snippet,
size_t byte_limit);

} // namespace base

#endif // BASE_TEST_LAUNCHER_TEST_LAUNCHER_H_
202 changes: 202 additions & 0 deletions base/test/launcher/test_launcher_unittest.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -9,13 +9,17 @@
#include "base/command_line.h"
#include "base/files/file_util.h"
#include "base/files/scoped_temp_dir.h"
#include "base/logging.h"
#include "base/no_destructor.h"
#include "base/process/launch.h"
#include "base/strings/strcat.h"
#include "base/strings/string_split.h"
#include "base/strings/string_util.h"
#include "base/test/launcher/test_launcher.h"
#include "base/test/launcher/test_launcher_test_utils.h"
#include "base/test/launcher/unit_test_launcher.h"
#include "base/test/multiprocess_test.h"
#include "base/test/scoped_logging_settings.h"
#include "base/test/task_environment.h"
#include "base/test/test_timeouts.h"
#include "base/threading/thread_task_runner_handle.h"
Expand Down Expand Up @@ -935,6 +939,204 @@ TEST(TestLauncherTools, GetTestOutputSnippetTest) {
"[ SKIPPED ] TestCase.ThirdTest (0 ms)\n");
}

void CheckTruncatationPreservesMessage(std::string message) {
// Ensure the inserted message matches the expected pattern.
constexpr char kExpected[] = R"(FATAL.*message\n)";
ASSERT_THAT(message, ::testing::ContainsRegex(kExpected));

const std::string snippet =
base::StrCat({"[ RUN ] SampleTestSuite.SampleTestName\n"
"Padding log message added for testing purposes\n"
"Padding log message added for testing purposes\n"
"Padding log message added for testing purposes\n"
"Padding log message added for testing purposes\n"
"Padding log message added for testing purposes\n"
"Padding log message added for testing purposes\n",
message,
"Padding log message added for testing purposes\n"
"Padding log message added for testing purposes\n"
"Padding log message added for testing purposes\n"
"Padding log message added for testing purposes\n"
"Padding log message added for testing purposes\n"
"Padding log message added for testing purposes\n"});

// Strip the stack trace off the end of message.
size_t line_end_pos = message.find("\n");
std::string first_line = message.substr(0, line_end_pos + 1);

const std::string result = TruncateSnippetFocused(snippet, 300);
EXPECT_TRUE(result.find(first_line) > 0);
EXPECT_EQ(result.length(), 300UL);
}

void MatchesFatalMessagesTest() {
// Use a static because only captureless lambdas can be converted to a
// function pointer for SetLogMessageHandler().
static base::NoDestructor<std::string> log_string;
logging::SetLogMessageHandler([](int severity, const char* file, int line,
size_t start,
const std::string& str) -> bool {
*log_string = str;
return true;
});
// Different Chrome test suites have different settings for their logs.
// E.g. unit tests may not show the process ID (as they are single process),
// whereas browser tests usually do (as they are multi-process). This
// affects how log messages are formatted and hence how the log criticality
// i.e. "FATAL", appears in the log message. We test the two extremes --
// all process IDs, timestamps present, and all not present. We also test
// the presence/absence of an extra logging prefix.
{
// Process ID, Thread ID, Timestamp and Tickcount.
logging::SetLogItems(true, true, true, true);
logging::SetLogPrefix(nullptr);
LOG(FATAL) << "message";
CheckTruncatationPreservesMessage(*log_string);
}
{
logging::SetLogItems(false, false, false, false);
logging::SetLogPrefix(nullptr);
LOG(FATAL) << "message";
CheckTruncatationPreservesMessage(*log_string);
}
{
// Process ID, Thread ID, Timestamp and Tickcount.
logging::SetLogItems(true, true, true, true);
logging::SetLogPrefix("my_log_prefix");
LOG(FATAL) << "message";
CheckTruncatationPreservesMessage(*log_string);
}
{
logging::SetLogItems(false, false, false, false);
logging::SetLogPrefix("my_log_prefix");
LOG(FATAL) << "message";
CheckTruncatationPreservesMessage(*log_string);
}
}

// Validates TestSnippetFocused correctly identifies fatal messages to
// retain during truncation.
TEST(TestLauncherTools, TruncateSnippetFocusedMatchesFatalMessagesTest) {
logging::ScopedLoggingSettings scoped_logging_settings;
#if BUILDFLAG(IS_CHROMEOS_ASH)
scoped_logging_settings.SetLogFormat(logging::LogFormat::LOG_FORMAT_SYSLOG);
#endif
MatchesFatalMessagesTest();
}

#if BUILDFLAG(IS_CHROMEOS_ASH)
// Validates TestSnippetFocused correctly identifies fatal messages to
// retain during truncation, for ChromeOS Ash.
TEST(TestLauncherTools, TruncateSnippetFocusedMatchesFatalMessagesCrosAshTest) {
logging::ScopedLoggingSettings scoped_logging_settings;
scoped_logging_settings.SetLogFormat(logging::LogFormat::LOG_FORMAT_CHROME);
MatchesFatalMessagesTest();
}
#endif

// Validate TestSnippetFocused truncates snippets correctly, regardless of
// whether fatal messages appear at the start, middle or end of the snippet.
TEST(TestLauncherTools, TruncateSnippetFocusedTest) {
// Test where FATAL message appears in the start of the log.
const std::string snippet =
"[ RUN ] "
"EndToEndTests/"
"EndToEndTest.WebTransportSessionUnidirectionalStreamSentEarly/"
"draft29_QBIC\n"
"[26219:26368:FATAL:tls_handshaker.cc(293)] 1-RTT secret(s) not set "
"yet.\n"
"#0 0x55619ad1fcdb in backtrace "
"/b/s/w/ir/cache/builder/src/third_party/llvm/compiler-rt/lib/asan/../"
"sanitizer_common/sanitizer_common_interceptors.inc:4205:13\n"
"#1 0x5561a6bdf519 in base::debug::CollectStackTrace(void**, unsigned "
"long) ./../../base/debug/stack_trace_posix.cc:845:39\n"
"#2 0x5561a69a1293 in StackTrace "
"./../../base/debug/stack_trace.cc:200:12\n"
"...\n";
const std::string result = TruncateSnippetFocused(snippet, 300);
EXPECT_EQ(
result,
"[ RUN ] EndToEndTests/EndToEndTest.WebTransportSessionUnidirection"
"alStreamSentEarly/draft29_QBIC\n"
"[26219:26368:FATAL:tls_handshaker.cc(293)] 1-RTT secret(s) not set "
"yet.\n"
"#0 0x55619ad1fcdb in backtrace /b/s/w/ir/cache/bui\n"
"<truncated (358 bytes)>\n"
"Trace ./../../base/debug/stack_trace.cc:200:12\n"
"...\n");
EXPECT_EQ(result.length(), 300UL);

// Test where FATAL message appears in the middle of the log.
const std::string snippet_two =
"[ RUN ] NetworkingPrivateApiTest.CreateSharedNetwork\n"
"Padding log information added for testing purposes\n"
"Padding log information added for testing purposes\n"
"Padding log information added for testing purposes\n"
"FATAL extensions_unittests[12666:12666]: [managed_network_configuration"
"_handler_impl.cc(525)] Check failed: !guid_str && !guid_str->empty().\n"
"#0 0x562f31dba779 base::debug::CollectStackTrace()\n"
"#1 0x562f31cdf2a3 base::debug::StackTrace::StackTrace()\n"
"#2 0x562f31cf4380 logging::LogMessage::~LogMessage()\n"
"#3 0x562f31cf4d3e logging::LogMessage::~LogMessage()\n";
const std::string result_two = TruncateSnippetFocused(snippet_two, 300);
EXPECT_EQ(
result_two,
"[ RUN ] NetworkingPriv\n"
"<truncated (210 bytes)>\n"
" added for testing purposes\n"
"FATAL extensions_unittests[12666:12666]: [managed_network_configuration"
"_handler_impl.cc(525)] Check failed: !guid_str && !guid_str->empty().\n"
"#0 0x562f31dba779 base::deb\n"
"<truncated (213 bytes)>\n"
":LogMessage::~LogMessage()\n");
EXPECT_EQ(result_two.length(), 300UL);

// Test where FATAL message appears at end of the log.
const std::string snippet_three =
"[ RUN ] All/PDFExtensionAccessibilityTreeDumpTest.Highlights/"
"linux\n"
"[6741:6741:0716/171816.818448:ERROR:power_monitor_device_source_stub.cc"
"(11)] Not implemented reached in virtual bool base::PowerMonitorDevice"
"Source::IsOnBatteryPower()\n"
"[6741:6741:0716/171816.818912:INFO:content_main_runner_impl.cc(1082)]"
" Chrome is running in full browser mode.\n"
"libva error: va_getDriverName() failed with unknown libva error,driver"
"_name=(null)\n"
"[6741:6741:0716/171817.688633:FATAL:agent_scheduling_group_host.cc(290)"
"] Check failed: message->routing_id() != MSG_ROUTING_CONTROL "
"(2147483647 vs. 2147483647)\n";
const std::string result_three = TruncateSnippetFocused(snippet_three, 300);
EXPECT_EQ(
result_three,
"[ RUN ] All/PDFExtensionAccessibilityTreeDumpTest.Hi\n"
"<truncated (432 bytes)>\n"
"Name() failed with unknown libva error,driver_name=(null)\n"
"[6741:6741:0716/171817.688633:FATAL:agent_scheduling_group_host.cc(290)"
"] Check failed: message->routing_id() != MSG_ROUTING_CONTROL "
"(2147483647 vs. 2147483647)\n");
EXPECT_EQ(result_three.length(), 300UL);

// Test where FATAL message does not appear.
const std::string snippet_four =
"[ RUN ] All/PassingTest/linux\n"
"Padding log line 1 added for testing purposes\n"
"Padding log line 2 added for testing purposes\n"
"Padding log line 3 added for testing purposes\n"
"Padding log line 4 added for testing purposes\n"
"Padding log line 5 added for testing purposes\n"
"Padding log line 6 added for testing purposes\n";
const std::string result_four = TruncateSnippetFocused(snippet_four, 300);
EXPECT_EQ(result_four,
"[ RUN ] All/PassingTest/linux\n"
"Padding log line 1 added for testing purposes\n"
"Padding log line 2 added for testing purposes\n"
"Padding lo\n<truncated (311 bytes)>\n"
"Padding log line 4 added for testing purposes\n"
"Padding log line 5 added for testing purposes\n"
"Padding log line 6 added for testing purposes\n");
EXPECT_EQ(result_four.length(), 300UL);
}

} // namespace

} // namespace base

0 comments on commit 078ced9

Please sign in to comment.