blob: eb6d1332daffc24282c08c8cd4155dcb0caa8d03 [file] [log] [blame]
// 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 <fstream>
#include <iostream>
#include <memory>
#include <string>
#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<blaze_util::BazelLogHandler> 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<blaze_util::BazelLogHandler> 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<blaze_util::BazelLogHandler> 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<blaze_util::BazelLogHandler> 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<blaze_util::BazelLogHandler> 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<blaze_util::BazelLogHandler> 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<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
TEST(LoggingTest, BazelLogHandler_DirectingLogsToBufferStreamWorks) {
// 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));
// Ask that the logs get output to a string buffer (keep a ptr to it so we can
// check its contents)
std::unique_ptr<std::stringstream> 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<blaze_util::BazelLogHandler> 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<std::stringstream> 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<blaze_util::BazelLogHandler> 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<std::stringstream> 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<blaze_util::BazelLogHandler> 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<std::stringstream> 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<blaze_util::BazelLogHandler> 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<std::ofstream> 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<blaze_util::BazelLogHandler> 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<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(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<blaze_util::BazelLogHandler> 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<blaze_util::BazelLogHandler> 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<blaze_util::BazelLogHandler> 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<blaze_util::BazelLogHandler> 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<blaze_util::BazelLogHandler> 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<blaze_util::BazelLogHandler> 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<blaze_util::BazelLogHandler> 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<std::ofstream> 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