// Copyright 2016 The Bazel Authors. All rights reserved. // // Licensed under the Apache License, Version 2.0 (the "License"); // you may not use this file except in compliance with the License. // You may obtain a copy of the License at // // http://www.apache.org/licenses/LICENSE-2.0 // // Unless required by applicable law or agreed to in writing, software // distributed under the License is distributed on an "AS IS" BASIS, // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. // See the License for the specific language governing permissions and // limitations under the License. #include #include #include #include #include "src/main/cpp/blaze_util_platform.h" #include "src/main/cpp/util/bazel_log_handler.h" #include "src/main/cpp/util/file.h" #include "src/main/cpp/util/logging.h" #include "src/main/cpp/util/path.h" #include "googlemock/include/gmock/gmock.h" #include "googletest/include/gtest/gtest.h" namespace blaze_util { using ::testing::HasSubstr; using ::testing::Not; // Note: gmock uses different regex syntax on different platforms. MatchesRegex // is still useful since the '.' wildcard can help match formatted log lines // like `[INFO 11:22:33.444 filename:134] message` // but should not be used for more fine grained testing. using ::testing::MatchesRegex; using ::testing::ContainsRegex; class LoggingTest : public ::testing::Test { protected: void SetUp() { // Set the value of $TMP first, because CaptureStderr retrieves a temp // directory path and on Windows, the corresponding function (GetTempPathA) // reads $TMP. blaze::SetEnv("TMP", blaze::GetPathEnv("TEST_TMPDIR")); } void TearDown() { blaze_util::SetLogHandler(nullptr); } }; TEST(LoggingTest, LogLevelNamesMatch) { EXPECT_STREQ("INFO", LogLevelName(LOGLEVEL_INFO)); EXPECT_STREQ("USER", LogLevelName(LOGLEVEL_USER)); EXPECT_STREQ("WARNING", LogLevelName(LOGLEVEL_WARNING)); EXPECT_STREQ("ERROR", LogLevelName(LOGLEVEL_ERROR)); EXPECT_STREQ("FATAL", LogLevelName(LOGLEVEL_FATAL)); } // Tests for when no log handler is set. TEST(LoggingTest, NoHandler_InfoLogsIgnored) { testing::internal::CaptureStderr(); blaze_util::SetLogHandler(nullptr); // Log something. std::string teststring = "test that the info log messages get ignored"; BAZEL_LOG(INFO) << teststring; // Check that stderr does not receive the message. std::string stderr_output = testing::internal::GetCapturedStderr(); EXPECT_THAT(stderr_output, Not(HasSubstr(teststring))); } TEST(LoggingTest, NoHandler_UserLogsPrinted) { testing::internal::CaptureStderr(); blaze_util::SetLogHandler(nullptr); // Log something. std::string teststring = "test that the user log messages are not ignored"; BAZEL_LOG(USER) << teststring; // Check that stderr receives the message. std::string stderr_output = testing::internal::GetCapturedStderr(); EXPECT_THAT(stderr_output, HasSubstr(teststring)); } TEST(LoggingTest, NoHandler_WarningsPrinted) { testing::internal::CaptureStderr(); blaze_util::SetLogHandler(nullptr); // Log something. BAZEL_LOG(WARNING) << "test that warnings are printed"; std::string expectedString = "WARNING: test that warnings are printed"; // Check that stderr receives the message. std::string stderr_output = testing::internal::GetCapturedStderr(); EXPECT_THAT(stderr_output, HasSubstr(expectedString)); } TEST(LoggingTest, NoHandler_ErrorsPrinted) { testing::internal::CaptureStderr(); blaze_util::SetLogHandler(nullptr); // Log something. BAZEL_LOG(ERROR) << "test that errors are printed"; std::string expectedError = "ERROR: test that errors are printed"; // Check that stderr receives the message. std::string stderr_output = testing::internal::GetCapturedStderr(); EXPECT_THAT(stderr_output, HasSubstr(expectedError)); } // Tests for the BazelLogHandler, with no call to SetLoggingOutputStream. TEST(LoggingTest, BazelLogHandler_DumpsToCerrAtDestruction) { // Set up logging and be prepared to capture stderr at destruction. testing::internal::CaptureStderr(); std::unique_ptr handler( new blaze_util::BazelLogHandler()); blaze_util::SetLogHandler(std::move(handler)); // Log something. std::string teststring = "test that log messages get dumped to stderr"; BAZEL_LOG(INFO) << teststring; // Check that stderr isn't getting anything yet. std::string stderr_output = testing::internal::GetCapturedStderr(); EXPECT_THAT(stderr_output, Not(HasSubstr(teststring))); testing::internal::CaptureStderr(); // Destruct the log handler and get the stderr remains. blaze_util::SetLogHandler(nullptr); stderr_output = testing::internal::GetCapturedStderr(); EXPECT_THAT(stderr_output, HasSubstr(teststring)); } // Tests for the BazelLogHandler's buffer after SetLoggingOutputStream(nullptr). TEST(LoggingTest, BazelLogHandler_DoesNotDumpToStderrIfOuputStreamSetToNull) { // Set up logging and be prepared to capture stderr at destruction. testing::internal::CaptureStderr(); std::unique_ptr handler( new blaze_util::BazelLogHandler()); blaze_util::SetLogHandler(std::move(handler)); // Log something. std::string teststring = "test that this log message is lost."; BAZEL_LOG(INFO) << teststring; blaze_util::SetLoggingOutputStream(nullptr); // Destruct the log handler and check if stderr got anything. blaze_util::SetLogHandler(nullptr); std::string stderr_output = testing::internal::GetCapturedStderr(); EXPECT_THAT(stderr_output, Not(HasSubstr(teststring))); } TEST(LoggingTest, BazelLogHandler_DoesNotPrintInfoLogsIfOuputStreamSetToNull) { // Set up logging and be prepared to capture stderr at destruction. testing::internal::CaptureStderr(); std::unique_ptr handler( new blaze_util::BazelLogHandler()); blaze_util::SetLogHandler(std::move(handler)); blaze_util::SetLoggingOutputStream(nullptr); std::string teststring = "test that the log message is lost."; BAZEL_LOG(INFO) << teststring; std::string stderr_output = testing::internal::GetCapturedStderr(); EXPECT_THAT(stderr_output, Not(HasSubstr(teststring))); } TEST(LoggingTest, BazelLogHandler_PrintsUserLogsEvenIfOuputStreamSetToNull) { // Set up logging and be prepared to capture stderr at destruction. testing::internal::CaptureStderr(); std::unique_ptr handler( new blaze_util::BazelLogHandler()); blaze_util::SetLogHandler(std::move(handler)); blaze_util::SetLoggingOutputStream(nullptr); std::string teststring = "some user message"; BAZEL_LOG(USER) << teststring; std::string stderr_output = testing::internal::GetCapturedStderr(); EXPECT_THAT(stderr_output, HasSubstr(teststring)); } TEST(LoggingTest, BazelLogHandler_PrintsWarningsEvenIfOuputStreamSetToNull) { // Set up logging and be prepared to capture stderr at destruction. testing::internal::CaptureStderr(); std::unique_ptr handler( new blaze_util::BazelLogHandler()); blaze_util::SetLogHandler(std::move(handler)); 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(expectedWarning)); } TEST(LoggingTest, BazelLogHandler_PrintsErrorsEvenIfOuputStreamSetToNull) { // Set up logging and be prepared to capture stderr at destruction. testing::internal::CaptureStderr(); std::unique_ptr handler( new blaze_util::BazelLogHandler()); blaze_util::SetLogHandler(std::move(handler)); 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(expectedError)); } TEST(LoggingTest, BazelLogHandler_BufferedInfoLogsGetLostEvenIfOutputStreamSetToNull) { // Set up logging and be prepared to capture stderr at destruction. testing::internal::CaptureStderr(); std::unique_ptr 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 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 TEST(LoggingTest, BazelLogHandler_DirectingLogsToBufferStreamWorks) { // Set up logging and be prepared to capture stderr at destruction. testing::internal::CaptureStderr(); std::unique_ptr handler( new blaze_util::BazelLogHandler()); blaze_util::SetLogHandler(std::move(handler)); // Ask that the logs get output to a string buffer (keep a ptr to it so we can // check its contents) std::unique_ptr stringbuf(new std::stringstream()); std::stringstream* stringbuf_ptr = stringbuf.get(); blaze_util::SetLoggingOutputStream(std::move(stringbuf)); std::string teststring = "testing log getting directed to a stringbuffer."; BAZEL_LOG(INFO) << teststring; // Check that output went to the buffer. std::string output(stringbuf_ptr->str()); EXPECT_THAT(output, HasSubstr(teststring)); // Check that the output never went to stderr. std::string stderr_output = testing::internal::GetCapturedStderr(); EXPECT_THAT(stderr_output, Not(HasSubstr(teststring))); } TEST(LoggingTest, BazelLogHandler_BufferedLogsSentToSpecifiedStream) { // Set up logging and be prepared to capture stderr at destruction. testing::internal::CaptureStderr(); std::unique_ptr handler( new blaze_util::BazelLogHandler()); blaze_util::SetLogHandler(std::move(handler)); std::string teststring = "test sending logs to the buffer before setting the output stream"; BAZEL_LOG(INFO) << teststring; // Check that stderr isn't getting anything. std::string stderr_output = testing::internal::GetCapturedStderr(); EXPECT_THAT(stderr_output, Not(HasSubstr(teststring))); testing::internal::CaptureStderr(); // Ask that the logs get output to a string buffer (keep a ptr to it so we can // check its contents) std::unique_ptr stringbuf(new std::stringstream()); std::stringstream* stringbuf_ptr = stringbuf.get(); blaze_util::SetLoggingOutputStream(std::move(stringbuf)); // Check that the buffered logs were sent. std::string output(stringbuf_ptr->str()); EXPECT_THAT(output, MatchesRegex(".INFO.* test sending logs to the buffer " "before setting the output stream\n")); // Check that the output did not go to stderr. stderr_output = testing::internal::GetCapturedStderr(); EXPECT_THAT(stderr_output, Not(HasSubstr(teststring))); } TEST(LoggingTest, BazelLogHandler_WarningsSentToBufferStream) { // Set up logging and be prepared to capture stderr at destruction. testing::internal::CaptureStderr(); std::unique_ptr handler( new blaze_util::BazelLogHandler()); blaze_util::SetLogHandler(std::move(handler)); // Ask that the logs get output to a string buffer (keep a ptr to it so we can // check its contents) std::unique_ptr stringbuf(new std::stringstream()); std::stringstream* stringbuf_ptr = stringbuf.get(); blaze_util::SetLoggingOutputStream(std::move(stringbuf)); std::string teststring = "test warning"; BAZEL_LOG(WARNING) << teststring; // Check that output went to the buffer. std::string output(stringbuf_ptr->str()); EXPECT_THAT(output, MatchesRegex(".WARNING.* test warning\n")); // Check that the output never went to stderr. std::string stderr_output = testing::internal::GetCapturedStderr(); EXPECT_THAT(stderr_output, Not(HasSubstr(teststring))); } TEST(LoggingTest, BazelLogHandler_ErrorsSentToBufferStream) { // Set up logging and be prepared to capture stderr at destruction. testing::internal::CaptureStderr(); std::unique_ptr handler( new blaze_util::BazelLogHandler()); blaze_util::SetLogHandler(std::move(handler)); // Ask that the logs get output to a string buffer (keep a ptr to it so we can // check its contents) std::unique_ptr stringbuf(new std::stringstream()); std::stringstream* stringbuf_ptr = stringbuf.get(); blaze_util::SetLoggingOutputStream(std::move(stringbuf)); std::string teststring = "test error"; BAZEL_LOG(ERROR) << teststring; // Check that output went to the buffer. std::string output(stringbuf_ptr->str()); EXPECT_THAT(output, MatchesRegex(".ERROR.* test error\n")); // Check that the output never went to stderr. std::string stderr_output = testing::internal::GetCapturedStderr(); EXPECT_THAT(stderr_output, Not(HasSubstr(teststring))); } TEST(LoggingTest, BazelLogHandler_ImpossibleFile) { // Set up logging and be prepared to capture stderr at destruction. testing::internal::CaptureStderr(); std::unique_ptr handler( new blaze_util::BazelLogHandler()); blaze_util::SetLogHandler(std::move(handler)); // Deliberately try to log to an impossible location, check that we error out. std::unique_ptr bad_logfile_stream_( new std::ofstream("/this/doesnt/exist.log", std::fstream::out)); blaze_util::SetLoggingOutputStream(std::move(bad_logfile_stream_)); // 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, MatchesRegex(".ERROR.* Provided stream failed.\n")); } // Tests for the BazelLogHandler & SetLoggingOutputStreamToStderr TEST(LoggingTest, BazelLogHandler_DirectingLogsToCerrWorks) { // Set up logging and be prepared to capture stderr at destruction. testing::internal::CaptureStderr(); std::unique_ptr handler( new blaze_util::BazelLogHandler()); blaze_util::SetLogHandler(std::move(handler)); // Ask that the logs get output to stderr blaze_util::SetLoggingOutputStreamToStderr(); // Log something. std::string teststring = "test that the log messages get directed to cerr"; BAZEL_LOG(INFO) << teststring; // 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)); } TEST(LoggingTest, BazelLogHandler_BufferedLogsGetDirectedToCerr) { // Set up logging and be prepared to capture stderr at destruction. testing::internal::CaptureStderr(); std::unique_ptr 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(INFO) << teststring; // Ask that the logs get output to stderr blaze_util::SetLoggingOutputStreamToStderr(); // 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)); } // We use the LoggingDeathTest test case to make sure that the death tests are // run in a single threaded environment, where it is safe to fork. These tests // are run before the other tests, which can be run in parallel. #if GTEST_HAS_DEATH_TEST using LoggingDeathTest = LoggingTest; TEST(LoggingDeathTest, NoHandler_FatalStatementUsesInternalErrorCode) { // When no handler is specified, we still expect fatal messages to get // printed to stderr. ASSERT_EXIT({ BAZEL_LOG(FATAL) << "something's wrong!"; }, ::testing::ExitedWithCode(37), "FATAL: something's wrong!"); } TEST(LoggingDeathTest, BazelLogHandler_UnsetOutputStream_FatalStatementUsesInternalErrorCode) { ASSERT_EXIT( { std::unique_ptr handler( new blaze_util::BazelLogHandler()); blaze_util::SetLogHandler(std::move(handler)); BAZEL_LOG(FATAL) << "something's wrong!"; }, ::testing::ExitedWithCode(37), "\\[FATAL .*\\] something's wrong!"); } TEST(LoggingDeathTest, BazelLogHandler_Deactivated_FatalStatementUsesInternalErrorCode) { ASSERT_EXIT( { std::unique_ptr handler( new blaze_util::BazelLogHandler()); blaze_util::SetLogHandler(std::move(handler)); blaze_util::SetLoggingOutputStream(nullptr); BAZEL_LOG(FATAL) << "something's wrong!"; }, ::testing::ExitedWithCode(37), "FATAL: something's wrong!"); } TEST(LoggingDeathTest, BazelLogHandler_Stderr_FatalStatementUsesInternalErrorCode) { ASSERT_EXIT( { std::unique_ptr handler( new blaze_util::BazelLogHandler()); blaze_util::SetLogHandler(std::move(handler)); blaze_util::SetLoggingOutputStreamToStderr(); BAZEL_LOG(FATAL) << "something's wrong!"; }, ::testing::ExitedWithCode(37), "\\[FATAL .*\\] something's wrong!"); } TEST(LoggingDeathTest, NoHandler_BazelDieDiesWithCustomExitCode) { ASSERT_EXIT({ BAZEL_DIE(42) << "dying with exit code 42."; }, ::testing::ExitedWithCode(42), "FATAL: dying with exit code 42."); } TEST(LoggingDeathTest, BazelLogHandler_UnsetOutputStream_BazelDieDiesWithCustomExitCode) { ASSERT_EXIT( { std::unique_ptr handler( new blaze_util::BazelLogHandler()); blaze_util::SetLogHandler(std::move(handler)); BAZEL_DIE(42) << "dying with exit code 42."; }, ::testing::ExitedWithCode(42), "\\[FATAL .*\\] dying with exit code 42."); } TEST(LoggingDeathTest, BazelLogHandler_Deactivated_BazelDieDiesWithCustomExitCode) { ASSERT_EXIT( { std::unique_ptr handler( new blaze_util::BazelLogHandler()); blaze_util::SetLogHandler(std::move(handler)); blaze_util::SetLoggingOutputStream(nullptr); BAZEL_DIE(42) << "dying with exit code 42."; }, ::testing::ExitedWithCode(42), "FATAL: dying with exit code 42."); } TEST(LoggingDeathTest, BazelLogHandler_Stderr_BazelDieDiesWithCustomExitCode) { ASSERT_EXIT( { std::unique_ptr handler( new blaze_util::BazelLogHandler()); blaze_util::SetLogHandler(std::move(handler)); blaze_util::SetLoggingOutputStreamToStderr(); BAZEL_DIE(42) << "dying with exit code 42."; }, ::testing::ExitedWithCode(42), "\\[FATAL .*\\] dying with exit code 42."); } TEST(LoggingDeathTest, BazelLogHandler_CustomStream_BazelDiePrintsToStderrAndCustomStream) { std::string logfile = blaze_util::JoinPath(blaze::GetPathEnv("TEST_TMPDIR"), "logfile"); ASSERT_EXIT( { std::unique_ptr handler( new blaze_util::BazelLogHandler()); blaze_util::SetLogHandler(std::move(handler)); // Ask that the logs get output to a file (the string buffer setup used // in the non-death tests doesn't work here.) std::unique_ptr logfile_stream_( new std::ofstream(logfile, std::fstream::out)); blaze_util::SetLoggingOutputStream(std::move(logfile_stream_)); BAZEL_DIE(42) << "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)); // Unlike in earlier tests, this string is read from a file, and since Windows // uses the newline '\r\n', compared to the linux \n, we prefer to keep the // test simple and not test the end of the line explicitly. EXPECT_THAT(output, ContainsRegex("\\[FATAL .*\\] dying with exit code 42.")); } #endif // GTEST_HAS_DEATH_TEST } // namespace blaze_util