Make sure that user-level log messages are not lost in a buffer if debug

logging is turned off.

WARNINGs, ERRORs, and simple USER messages get printed to stderr when debug logging is disabled, which it is by default. However, before this change, these were lost if they were sent to BAZEL_LOG before Bazel knew whether or not debug logging was requested. This fixes that by maintaining separate buffers, and dumping only the appropriate one to stderr once we know whether or not it is wanted.

Maintaining the separate buffer also allows for it to be easy to, in the future, allow logging to multiple places, if we are logging details to a file and user-level details to stderr, for example.

RELNOTES: None.
PiperOrigin-RevId: 206960686

2 files changed, 62 insertions, 11 deletions

diff --git a/src/test/cpp/util/logging_test.cc b/src/test/cpp/util/logging_test.cc
index d48c177e75..7891a07ed4 100644
--- a/src/test/cpp/util/logging_test.cc
+++ b/src/test/cpp/util/logging_test.cc
@@ -60,7 +60,7 @@ TEST(LoggingTest, NoHandler_InfoLogsIgnored) {
   blaze_util::SetLogHandler(nullptr);
 
   // Log something.
-  std::string teststring = "test that the log messages get ignored";
+  std::string teststring = "test that the info log messages get ignored";
   BAZEL_LOG(INFO) << teststring;
 
   // Check that stderr does not receive the message.
@@ -131,8 +131,7 @@ TEST(LoggingTest, BazelLogHandler_DumpsToCerrAtDestruction) {
   EXPECT_THAT(stderr_output, HasSubstr(teststring));
 }
 
-// Tests for the BazelLogHandler, deactivated by
-// SetLoggingOutputStream(nullptr).
+// Tests for the BazelLogHandler's buffer after SetLoggingOutputStream(nullptr).
 
 TEST(LoggingTest, BazelLogHandler_DoesNotDumpToStderrIfOuputStreamSetToNull) {
   // Set up logging and be prepared to capture stderr at destruction.
@@ -191,9 +190,10 @@ TEST(LoggingTest, BazelLogHandler_PrintsWarningsEvenIfOuputStreamSetToNull) {
   blaze_util::SetLoggingOutputStream(nullptr);
 
   BAZEL_LOG(WARNING) << "this is a warning";
+  std::string expectedWarning = "WARNING: this is a warning";
 
   std::string stderr_output = testing::internal::GetCapturedStderr();
-  EXPECT_THAT(stderr_output, HasSubstr("WARNING: this is a warning"));
+  EXPECT_THAT(stderr_output, HasSubstr(expectedWarning));
 }
 
 TEST(LoggingTest, BazelLogHandler_PrintsErrorsEvenIfOuputStreamSetToNull) {
@@ -205,9 +205,56 @@ TEST(LoggingTest, BazelLogHandler_PrintsErrorsEvenIfOuputStreamSetToNull) {
   blaze_util::SetLoggingOutputStream(nullptr);
 
   BAZEL_LOG(ERROR) << "this is an error, alert!";
+  std::string expectedError = "ERROR: this is an error, alert!";
 
   std::string stderr_output = testing::internal::GetCapturedStderr();
-  EXPECT_THAT(stderr_output, HasSubstr("ERROR: this is an error, alert!\n"));
+  EXPECT_THAT(stderr_output, HasSubstr(expectedError));
+}
+
+TEST(LoggingTest,
+     BazelLogHandler_BufferedInfoLogsGetLostEvenIfOutputStreamSetToNull) {
+  // Set up logging and be prepared to capture stderr at destruction.
+  testing::internal::CaptureStderr();
+  std::unique_ptr<blaze_util::BazelLogHandler> handler(
+      new blaze_util::BazelLogHandler());
+  blaze_util::SetLogHandler(std::move(handler));
+
+  // Log something before telling the loghandler where to send it.
+  std::string teststring = "this message should be lost.";
+  BAZEL_LOG(INFO) << teststring;
+
+  // Ask that the debug logs not be kept.
+  blaze_util::SetLoggingOutputStream(nullptr);
+
+  // Set a null log handler, which causes the BazelLogHandler to be destructed.
+  // This prompts its logs to be flushed, so we can capture them.
+  blaze_util::SetLogHandler(nullptr);
+  std::string stderr_output = testing::internal::GetCapturedStderr();
+  EXPECT_THAT(stderr_output, Not(HasSubstr(teststring)));
+}
+
+TEST(LoggingTest,
+     BazelLogHandler_BufferedWarningLogsRedirectedAfterOutputStreamSetToNull) {
+  // Set up logging and be prepared to capture stderr at destruction.
+  testing::internal::CaptureStderr();
+  std::unique_ptr<blaze_util::BazelLogHandler> handler(
+      new blaze_util::BazelLogHandler());
+  blaze_util::SetLogHandler(std::move(handler));
+
+  // Log something before telling the loghandler where to send it.
+  std::string teststring = "test that this message gets directed to cerr";
+  BAZEL_LOG(WARNING) << teststring;
+  std::string expectedWarning =
+      "WARNING: test that this message gets directed to cerr";
+
+  // Ask that the debug logs not be kept.
+  blaze_util::SetLoggingOutputStream(nullptr);
+
+  // Set a null log handler, which causes the BazelLogHandler to be destructed.
+  // This prompts its logs to be flushed, so we can capture them.
+  blaze_util::SetLogHandler(nullptr);
+  std::string stderr_output = testing::internal::GetCapturedStderr();
+  EXPECT_THAT(stderr_output, HasSubstr(expectedWarning));
 }
 
 // Tests for the BazelLogHandler & SetLoggingOutputStream
@@ -332,7 +379,8 @@ TEST(LoggingTest, BazelLogHandler_ImpossibleFile) {
       new std::ofstream("/this/doesnt/exist.log", std::fstream::out));
   blaze_util::SetLoggingOutputStream(std::move(bad_logfile_stream_));
 
-  // Cause the logs to be flushed, and capture them.
+  // Set a null log handler, which causes the BazelLogHandler to be destructed.
+  // This prompts its logs to be flushed, so we can capture them..
   blaze_util::SetLogHandler(nullptr);
   std::string stderr_output = testing::internal::GetCapturedStderr();
   EXPECT_THAT(stderr_output,
@@ -355,7 +403,8 @@ TEST(LoggingTest, BazelLogHandler_DirectingLogsToCerrWorks) {
   std::string teststring = "test that the log messages get directed to cerr";
   BAZEL_LOG(INFO) << teststring;
 
-  // Cause the logs to be flushed, and capture them.
+  // Set a null log handler, which causes the BazelLogHandler to be destructed.
+  // This prompts its logs to be flushed, so we can capture them.
   blaze_util::SetLogHandler(nullptr);
   std::string stderr_output = testing::internal::GetCapturedStderr();
   EXPECT_THAT(stderr_output, HasSubstr(teststring));
@@ -375,7 +424,8 @@ TEST(LoggingTest, BazelLogHandler_BufferedLogsGetDirectedToCerr) {
   // Ask that the logs get output to stderr
   blaze_util::SetLoggingOutputStreamToStderr();
 
-  // Cause the logs to be flushed, and capture them.
+  // Set a null log handler, which causes the BazelLogHandler to be destructed.
+  // This prompts its logs to be flushed, so we can capture them.
   blaze_util::SetLogHandler(nullptr);
   std::string stderr_output = testing::internal::GetCapturedStderr();
   EXPECT_THAT(stderr_output, HasSubstr(teststring));
@@ -496,9 +546,7 @@ TEST(LoggingDeathTest,
 
         BAZEL_DIE(42) << "dying with exit code 42.";
       },
-      ::testing::ExitedWithCode(42),
-      "\\[bazel FATAL .*\\] dying with exit code 42.");
-
+      ::testing::ExitedWithCode(42), "FATAL: dying with exit code 42.");
   // Check that the error is also in the custom stream.
   std::string output;
   ASSERT_TRUE(blaze_util::ReadFile(logfile, &output));
diff --git a/src/test/shell/integration/bazel_command_log_test.sh b/src/test/shell/integration/bazel_command_log_test.sh
index 3e7443c353..8094e65a19 100755
--- a/src/test/shell/integration/bazel_command_log_test.sh
+++ b/src/test/shell/integration/bazel_command_log_test.sh
@@ -31,6 +31,8 @@ function strip_lines_from_bazel_cc() {
   # file). In newer versions of gnu sed there is a -i option to edit in place.
 
   # different sandbox_root result in different startup options
+  # TODO(b/5568649): Remove host_javabase from tests and stop removing the
+  # warning from the stderr output.
   clean_log=$(\
     sed \
     -e "/^INFO: Reading 'startup' options from /d" \
@@ -41,6 +43,7 @@ function strip_lines_from_bazel_cc() {
     -e '/^Killed non-responsive server process/d' \
     -e '/server needs to be killed, because the startup options are different/d' \
     -e '/^WARNING: Waiting for server process to terminate (waited 5 seconds, waiting at most 60)$/d' \
+    -e '/^WARNING: The startup option --host_javabase is deprecated; prefer --server_javabase.$/d' \
     $TEST_log)
 
   echo "$clean_log" > $TEST_log