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
diff --git a/src/main/cpp/util/bazel_log_handler.cc b/src/main/cpp/util/bazel_log_handler.cc
index a3406e9..be525ac 100644
--- a/src/main/cpp/util/bazel_log_handler.cc
+++ b/src/main/cpp/util/bazel_log_handler.cc
@@ -28,7 +28,8 @@
BazelLogHandler::BazelLogHandler()
: output_stream_set_(false),
logging_deactivated_(false),
- buffer_stream_(new std::stringstream()),
+ user_buffer_stream_(new std::stringstream()),
+ debug_buffer_stream_(new std::stringstream()),
output_stream_(),
owned_output_stream_() {}
@@ -38,8 +39,8 @@
// otherwise, flush the stream.
if (output_stream_ != nullptr) {
output_stream_->flush();
- } else if (buffer_stream_ != nullptr) {
- std::cerr << buffer_stream_->rdbuf();
+ } else if (debug_buffer_stream_ != nullptr) {
+ std::cerr << debug_buffer_stream_->rdbuf();
} else {
std::cerr << "Illegal state - neither a logfile nor a logbuffer "
<< "existed at program end." << std::endl;
@@ -47,41 +48,66 @@
}
}
+// Messages intended for the user (level USER, along with WARNINGs an ERRORs)
+// should be printed even if debug level logging was not requested.
+void PrintUserLevelMessageToStream(std::ostream* stream, LogLevel level,
+ const std::string& message) {
+ if (level == LOGLEVEL_USER) {
+ (*stream) << message << std::endl;
+ } else if (level > LOGLEVEL_USER) {
+ (*stream) << LogLevelName(level) << ": " << message << std::endl;
+ }
+ // If level < USER, this is an INFO message. It's useful for debugging but
+ // should not be printed to the user unless the user has asked for debugging
+ // output. We ignore it here.
+}
+
+// For debug logs, print all logs, both debug logging and USER logs and above,
+// along with information about where the log message came from.
+void PrintDebugLevelMessageToStream(std::ostream* stream,
+ const std::string& filename, int line,
+ LogLevel level,
+ const std::string& message) {
+ (*stream) << "[bazel " << LogLevelName(level) << " " << filename << ":"
+ << line << "] " << message << std::endl;
+}
+
void BazelLogHandler::HandleMessage(LogLevel level, const std::string& filename,
int line, const std::string& message,
int exit_code) {
- // Select the appropriate stream to log to.
- std::ostream* log_stream;
if (logging_deactivated_) {
// If the output stream was explicitly deactivated, never print INFO
// messages, but messages of level USER and above should always be printed,
// as should warnings and errors. Omit the debug-level file and line number
// information, though.
- if (level == LOGLEVEL_USER) {
- std::cerr << message << std::endl;
- } else if (level > LOGLEVEL_USER) {
- std::cerr << LogLevelName(level) << ": " << message << std::endl;
- }
-
+ PrintUserLevelMessageToStream(&std::cerr, level, message);
if (level == LOGLEVEL_FATAL) {
std::exit(exit_code);
}
return;
- } else if (output_stream_ == nullptr) {
- log_stream = buffer_stream_.get();
- } else {
- log_stream = output_stream_;
}
- (*log_stream) << "[bazel " << LogLevelName(level) << " " << filename << ":"
- << line << "] " << message << std::endl;
+ if (output_stream_ == nullptr) {
+ // If we haven't decided whether messages should be logged to debug levels
+ // or not, buffer each version. This is redundant for USER levels and above,
+ // but is to make sure we can provide the right output to the user once we
+ // know that they do or do not want debug level information.
+ PrintUserLevelMessageToStream(user_buffer_stream_.get(), level, message);
+ PrintDebugLevelMessageToStream(debug_buffer_stream_.get(), filename, line,
+ level, message);
+ } else {
+ // If an output stream has been specifically set, it is for the full suite
+ // of log messages. We don't print the user messages separately here as they
+ // are included.
+ PrintDebugLevelMessageToStream(output_stream_, filename, line, level,
+ message);
+ }
// If we have a fatal message, exit with the provided error code.
if (level == LOGLEVEL_FATAL) {
if (owned_output_stream_ != nullptr) {
// If this is is not being printed to stderr but to a custom stream,
// also print the error message to stderr.
- std::cerr << "[bazel " << LogLevelName(level) << " " << filename << ":"
- << line << "] " << message << std::endl;
+ PrintUserLevelMessageToStream(&std::cerr, level, message);
}
std::exit(exit_code);
}
@@ -94,7 +120,11 @@
BAZEL_CHECK(!output_stream_set_) << "Tried to set log output a second time";
output_stream_set_ = true;
- FlushBufferToNewStreamAndSet(&std::cerr);
+ FlushBufferToNewStreamAndSet(debug_buffer_stream_.get(), &std::cerr);
+ debug_buffer_stream_ = nullptr;
+ // The user asked for debug level information, which includes the user
+ // messages. We can discard the separate buffer at this point.
+ user_buffer_stream_ = nullptr;
}
void BazelLogHandler::SetOutputStream(
@@ -107,29 +137,39 @@
if (new_output_stream == nullptr) {
logging_deactivated_ = true;
- buffer_stream_ = nullptr;
+ // Flush the buffered user-level messages to stderr - these are messages
+ // that are meant for the user even when debug logging is not set.
+ FlushBufferToNewStreamAndSet(user_buffer_stream_.get(), &std::cerr);
+
+ user_buffer_stream_ = nullptr;
+ // We discard the debug level logs, the user level ones were enough to
+ // inform the user and debug logging was not requested.
+ debug_buffer_stream_ = nullptr;
return;
}
owned_output_stream_ = std::move(new_output_stream);
- FlushBufferToNewStreamAndSet(owned_output_stream_.get());
+ if (owned_output_stream_->fail()) {
+ // If opening the stream failed, continue buffering and have the logs
+ // dump to stderr at shutdown.
+ BAZEL_LOG(ERROR) << "Provided stream failed.";
+ return;
+ }
+ FlushBufferToNewStreamAndSet(debug_buffer_stream_.get(),
+ owned_output_stream_.get());
+ debug_buffer_stream_ = nullptr;
+ // The user asked for debug level information, which includes the user
+ // messages. We can discard the separate buffer at this point.
+ user_buffer_stream_ = nullptr;
}
void BazelLogHandler::FlushBufferToNewStreamAndSet(
- std::ostream* new_output_stream) {
+ std::stringstream* buffer, std::ostream* new_output_stream) {
// Flush the buffer to the new stream, and print new log lines to it.
output_stream_ = new_output_stream;
- if (output_stream_->fail()) {
- // If opening the stream failed, continue buffering and have the logs
- // dump to stderr at shutdown.
- output_stream_ = nullptr;
- BAZEL_LOG(ERROR) << "Provided stream failed.";
- } else {
// Transfer the contents of the buffer to the new stream, then remove the
// buffer.
- (*output_stream_) << buffer_stream_->str();
- buffer_stream_ = nullptr;
- output_stream_->flush();
- }
+ (*output_stream_) << buffer->str();
+ output_stream_->flush();
}
} // namespace blaze_util
diff --git a/src/main/cpp/util/bazel_log_handler.h b/src/main/cpp/util/bazel_log_handler.h
index 50c8176..3ca8f56 100644
--- a/src/main/cpp/util/bazel_log_handler.h
+++ b/src/main/cpp/util/bazel_log_handler.h
@@ -39,10 +39,12 @@
void SetOutputStreamToStderr() override;
private:
- void FlushBufferToNewStreamAndSet(std::ostream* new_output_stream);
+ void FlushBufferToNewStreamAndSet(std::stringstream* buffer,
+ std::ostream* new_output_stream);
bool output_stream_set_;
bool logging_deactivated_;
- std::unique_ptr<std::stringstream> buffer_stream_;
+ std::unique_ptr<std::stringstream> user_buffer_stream_;
+ std::unique_ptr<std::stringstream> debug_buffer_stream_;
// The actual output_stream to which all logs will be sent.
std::ostream* output_stream_;
// A unique pts to the output_stream, if we need to keep ownership of the
diff --git a/src/test/cpp/util/logging_test.cc b/src/test/cpp/util/logging_test.cc
index d48c177..7891a07 100644
--- a/src/test/cpp/util/logging_test.cc
+++ b/src/test/cpp/util/logging_test.cc
@@ -60,7 +60,7 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
// 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 @@
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 3e7443c..8094e65 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 @@
# 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 @@
-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
