From 7383976083bfd66f6bb5c4d4a288111b81731c70 Mon Sep 17 00:00:00 2001 From: ccalvarin Date: Fri, 23 Mar 2018 15:35:00 -0700 Subject: Fold in warning and error output into client logging. To replace blaze_util::die and blaze_util::pdie as well, FATAL statements need to accept blaze exit codes. RELNOTES: None. PiperOrigin-RevId: 190285798 --- WORKSPACE | 2 + src/main/cpp/blaze.cc | 30 ++- src/main/cpp/blaze_util_freebsd.cc | 13 +- src/main/cpp/blaze_util_linux.cc | 13 +- src/main/cpp/blaze_util_windows.cc | 12 +- src/main/cpp/util/BUILD | 9 +- src/main/cpp/util/bazel_log_handler.cc | 12 +- src/main/cpp/util/errors.cc | 24 +-- src/main/cpp/util/errors.h | 2 - src/main/cpp/util/file_windows.cc | 6 +- src/main/cpp/util/logging.cc | 27 ++- src/test/cpp/util/logging_test.cc | 236 ++++++++++++++++++--- .../shell/bazel/testdata/embedded_tools_srcs_deps | 1 + src/test/shell/integration/client_test.sh | 101 +++++---- 14 files changed, 335 insertions(+), 153 deletions(-) diff --git a/WORKSPACE b/WORKSPACE index cdf502da2d..644cb899ee 100644 --- a/WORKSPACE +++ b/WORKSPACE @@ -141,6 +141,8 @@ http_archive( sha256 = "62797e7cd7cc959419710cd25b075b5f5b247da0e8214d47bf5af9b32128fb0d", ) +# We're pinning to a commit because this project does not have a recent release. +# Nothing special about this commit, though. http_archive( name = "com_google_googletest", urls = [ diff --git a/src/main/cpp/blaze.cc b/src/main/cpp/blaze.cc index 60b0bcab71..be52c2f953 100644 --- a/src/main/cpp/blaze.cc +++ b/src/main/cpp/blaze.cc @@ -72,7 +72,6 @@ using blaze_util::die; using blaze_util::pdie; -using blaze_util::PrintWarning; namespace blaze { @@ -729,13 +728,13 @@ static void StartStandalone(const WorkspaceLayout *workspace_layout, if (!command_arguments.empty() && command == "shutdown") { string product = globals->options->product_name; blaze_util::ToLower(&product); - PrintWarning( - "Running command \"shutdown\" in batch mode. Batch mode " - "is triggered\nwhen not running %s within a workspace. If you " - "intend to shutdown an\nexisting %s server, run \"%s " - "shutdown\" from the directory where\nit was started.", - globals->options->product_name.c_str(), - globals->options->product_name.c_str(), product.c_str()); + BAZEL_LOG(WARNING) + << "Running command \"shutdown\" in batch mode. Batch mode is " + "triggered\nwhen not running " + << globals->options->product_name + << " within a workspace. If you intend to shutdown an\nexisting " + << globals->options->product_name << " server, run \"" << product + << " shutdown\" from the directory where\nit was started."; } vector jvm_args_vector = GetArgumentArray(workspace_layout); if (!command.empty()) { @@ -1161,10 +1160,9 @@ static void KillRunningServerIfDifferentStartupOptions( // mortal coil. if (ServerNeedsToBeKilled(arguments, GetArgumentArray(workspace_layout))) { globals->restart_reason = NEW_OPTIONS; - PrintWarning( - "Running %s server needs to be killed, because the " - "startup options are different.", - globals->options->product_name.c_str()); + BAZEL_LOG(WARNING) << "Running " << globals->options->product_name + << " server needs to be killed, because the startup " + "options are different."; server->KillRunningServer(); } } @@ -1363,7 +1361,7 @@ static void ComputeBaseDirectories(const WorkspaceLayout *workspace_layout, // of '--client_env'. static void PrepareEnvironmentForJvm() { if (!blaze::GetEnv("http_proxy").empty()) { - PrintWarning("ignoring http_proxy in environment."); + BAZEL_LOG(WARNING) << "ignoring http_proxy in environment."; blaze::UnsetEnv("http_proxy"); } @@ -1372,18 +1370,18 @@ static void PrepareEnvironmentForJvm() { // specified, the JVM fails to create threads. See thread_stack_regtest. // This is also provoked by LD_LIBRARY_PATH=/usr/lib/debug, // or anything else that causes the JVM to use LinuxThreads. - PrintWarning("ignoring LD_ASSUME_KERNEL in environment."); + BAZEL_LOG(WARNING) << "ignoring LD_ASSUME_KERNEL in environment."; blaze::UnsetEnv("LD_ASSUME_KERNEL"); } if (!blaze::GetEnv("LD_PRELOAD").empty()) { - PrintWarning("ignoring LD_PRELOAD in environment."); + BAZEL_LOG(WARNING) << "ignoring LD_PRELOAD in environment."; blaze::UnsetEnv("LD_PRELOAD"); } if (!blaze::GetEnv("_JAVA_OPTIONS").empty()) { // This would override --host_jvm_args - PrintWarning("ignoring _JAVA_OPTIONS in environment."); + BAZEL_LOG(WARNING) << "ignoring _JAVA_OPTIONS in environment."; blaze::UnsetEnv("_JAVA_OPTIONS"); } diff --git a/src/main/cpp/blaze_util_freebsd.cc b/src/main/cpp/blaze_util_freebsd.cc index 4ff2278b54..5c516785f8 100644 --- a/src/main/cpp/blaze_util_freebsd.cc +++ b/src/main/cpp/blaze_util_freebsd.cc @@ -32,6 +32,7 @@ #include "src/main/cpp/util/errors.h" #include "src/main/cpp/util/exit_code.h" #include "src/main/cpp/util/file.h" +#include "src/main/cpp/util/logging.h" #include "src/main/cpp/util/port.h" #include "src/main/cpp/util/strings.h" @@ -39,7 +40,6 @@ namespace blaze { using blaze_util::die; using blaze_util::pdie; -using blaze_util::PrintWarning; using std::string; string GetOutputRoot() { @@ -58,16 +58,15 @@ string GetOutputRoot() { void WarnFilesystemType(const string &output_base) { struct statfs buf = {}; if (statfs(output_base.c_str(), &buf) < 0) { - PrintWarning("couldn't get file system type information for '%s': %s", - output_base.c_str(), strerror(errno)); + BAZEL_LOG(WARNING) << "couldn't get file system type information for '" + << output_base << "': " << strerror(errno); return; } if (strcmp(buf.f_fstypename, "nfs") == 0) { - PrintWarning( - "Output base '%s' is on NFS. This may lead " - "to surprising failures and undetermined behavior.", - output_base.c_str()); + BAZEL_LOG(WARNING) << "Output base '" << output_base + << "' is on NFS. This may lead to surprising failures " + "and undetermined behavior."; } } diff --git a/src/main/cpp/blaze_util_linux.cc b/src/main/cpp/blaze_util_linux.cc index 72eccb2d9a..82c3b991ae 100644 --- a/src/main/cpp/blaze_util_linux.cc +++ b/src/main/cpp/blaze_util_linux.cc @@ -31,6 +31,7 @@ #include "src/main/cpp/util/errors.h" #include "src/main/cpp/util/exit_code.h" #include "src/main/cpp/util/file.h" +#include "src/main/cpp/util/logging.h" #include "src/main/cpp/util/port.h" #include "src/main/cpp/util/strings.h" @@ -38,7 +39,6 @@ namespace blaze { using blaze_util::die; using blaze_util::pdie; -using blaze_util::PrintWarning; using std::string; using std::vector; @@ -68,16 +68,15 @@ string GetOutputRoot() { void WarnFilesystemType(const string& output_base) { struct statfs buf = {}; if (statfs(output_base.c_str(), &buf) < 0) { - PrintWarning("couldn't get file system type information for '%s': %s", - output_base.c_str(), strerror(errno)); + BAZEL_LOG(WARNING) << "couldn't get file system type information for '" + << output_base << "': " << strerror(errno); return; } if (buf.f_type == NFS_SUPER_MAGIC) { - PrintWarning( - "Output base '%s' is on NFS. This may lead " - "to surprising failures and undetermined behavior.", - output_base.c_str()); + BAZEL_LOG(WARNING) << "Output base '" << output_base + << "' is on NFS. This may lead to surprising failures " + "and undetermined behavior."; } } diff --git a/src/main/cpp/blaze_util_windows.cc b/src/main/cpp/blaze_util_windows.cc index d49e128e11..24f72d28d4 100644 --- a/src/main/cpp/blaze_util_windows.cc +++ b/src/main/cpp/blaze_util_windows.cc @@ -752,11 +752,11 @@ bool SymlinkDirectories(const string &posix_target, const string &posix_name) { posix_target.c_str(), posix_name.c_str(), posix_name.c_str()); return false; } - wstring error(CreateJunction(name, target)); - if (!error.empty()) { - blaze_util::PrintError("SymlinkDirectories(%s, %s): CreateJunction: %S", - posix_target.c_str(), posix_name.c_str(), - error.c_str()); + wstring werror(CreateJunction(name, target)); + if (!werror.empty()) { + string error(blaze_util::WstringToCstring(werror.c_str()).get()); + BAZEL_LOG(ERROR) << "SymlinkDirectories(" << posix_target << ", " + << posix_name << "): CreateJunction: " << error; return false; } return true; @@ -1397,6 +1397,8 @@ void DetectBashOrDie() { // Set process environment variable. blaze::SetEnv("BAZEL_SH", bash); } else { + // TODO(bazel-team) should this be printed to stderr? If so, it should use + // BAZEL_LOG(ERROR) printf( "Bazel on Windows requires bash.exe and other Unix tools, but we could " "not find them.\n" diff --git a/src/main/cpp/util/BUILD b/src/main/cpp/util/BUILD index 11db4ca047..66bd722dbc 100644 --- a/src/main/cpp/util/BUILD +++ b/src/main/cpp/util/BUILD @@ -54,6 +54,7 @@ cc_library( deps = [ ":blaze_exit_code", ":errors", + ":logging", ":strings", ] + select({ "//src/conditions:windows": ["//src/main/native/windows:lib-file"], @@ -72,7 +73,11 @@ cc_library( ":ijar", "//src/main/cpp:__subpackages__", ], - deps = [":port"], + deps = [ + ":logging", + ":port", + ":strings", + ], ) cc_library( @@ -93,6 +98,7 @@ cc_library( srcs = ["logging.cc"], hdrs = ["logging.h"], visibility = ["//visibility:public"], + deps = [":blaze_exit_code"], ) cc_library( @@ -101,6 +107,7 @@ cc_library( hdrs = ["bazel_log_handler.h"], visibility = ["//visibility:public"], deps = [ + ":blaze_exit_code", ":file", ":logging", ], diff --git a/src/main/cpp/util/bazel_log_handler.cc b/src/main/cpp/util/bazel_log_handler.cc index b0ebeb49f7..31c173d289 100644 --- a/src/main/cpp/util/bazel_log_handler.cc +++ b/src/main/cpp/util/bazel_log_handler.cc @@ -19,6 +19,7 @@ #include #include +#include "src/main/cpp/util/exit_code.h" #include "src/main/cpp/util/file.h" #include "src/main/cpp/util/logging.h" @@ -51,11 +52,13 @@ void BazelLogHandler::HandleMessage(LogLevel level, const std::string& filename, // Select the appropriate stream to log to. std::ostream* log_stream; if (logging_deactivated_) { - // Do nothing if the output stream was explicitly deactivated, unless the - // level is USER, in which case the message is meant to be user-visible - // regardless of logging settings. + // If the output stream was explicitly deactivated, never print INFO + // messages, but USER 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; } return; } else if (output_stream_ == nullptr) { @@ -72,7 +75,8 @@ void BazelLogHandler::HandleMessage(LogLevel level, const std::string& filename, if (level == LOGLEVEL_FATAL) { std::cerr << "[bazel " << LogLevelName(level) << " " << filename << ":" << line << "] " << message << std::endl; - std::abort(); + // TODO(b/32967056) pass correct exit code information. + std::exit(blaze_exit_code::INTERNAL_ERROR); } } diff --git a/src/main/cpp/util/errors.cc b/src/main/cpp/util/errors.cc index 4fc6190e98..b337809325 100644 --- a/src/main/cpp/util/errors.cc +++ b/src/main/cpp/util/errors.cc @@ -19,8 +19,11 @@ #include #include +#include "src/main/cpp/util/logging.h" + namespace blaze_util { +// TODO(b/32967056) This should be a FATAL log statement void die(const int exit_status, const char *format, ...) { va_list ap; va_start(ap, format); @@ -30,6 +33,7 @@ void die(const int exit_status, const char *format, ...) { exit(exit_status); } +// TODO(b/32967056) This should be a FATAL log statement void pdie(const int exit_status, const char *format, ...) { const char *errormsg = GetLastErrorString().c_str(); fprintf(stderr, "Error: "); @@ -41,24 +45,4 @@ void pdie(const int exit_status, const char *format, ...) { exit(exit_status); } -void PrintError(const char *format, ...) { - const char *errormsg = GetLastErrorString().c_str(); - fprintf(stderr, "ERROR: "); - va_list ap; - va_start(ap, format); - vfprintf(stderr, format, ap); - va_end(ap); - fprintf(stderr, ": %s\n", errormsg); -} - -void PrintWarning(const char *format, ...) { - va_list args; - - va_start(args, format); - fputs("WARNING: ", stderr); - vfprintf(stderr, format, args); - fputc('\n', stderr); - va_end(args); -} - } // namespace blaze_util diff --git a/src/main/cpp/util/errors.h b/src/main/cpp/util/errors.h index 62f1b3c90a..4bea4228de 100644 --- a/src/main/cpp/util/errors.h +++ b/src/main/cpp/util/errors.h @@ -29,8 +29,6 @@ void die(const int exit_status, const char *format, ...) ATTRIBUTE_NORETURN // Prints "Error: : \n", and exits nonzero. void pdie(const int exit_status, const char *format, ...) ATTRIBUTE_NORETURN PRINTF_ATTRIBUTE(2, 3); -void PrintError(const char *format, ...) PRINTF_ATTRIBUTE(1, 2); -void PrintWarning(const char *format, ...) PRINTF_ATTRIBUTE(1, 2); // Returns the last error as a platform-specific error message. // The string will also contain the platform-specific error code itself diff --git a/src/main/cpp/util/file_windows.cc b/src/main/cpp/util/file_windows.cc index fd63214574..4768f5cd5c 100644 --- a/src/main/cpp/util/file_windows.cc +++ b/src/main/cpp/util/file_windows.cc @@ -23,6 +23,7 @@ #include "src/main/cpp/util/errors.h" #include "src/main/cpp/util/exit_code.h" #include "src/main/cpp/util/file.h" +#include "src/main/cpp/util/logging.h" #include "src/main/cpp/util/strings.h" #include "src/main/native/windows/file.h" #include "src/main/native/windows/util.h" @@ -405,9 +406,8 @@ bool MsysRoot::Get(string* path) { } else { const char* value2 = getenv("BAZEL_SH"); if (value2 == nullptr || value2[0] == '\0') { - PrintError( - "BAZEL_SH environment variable is not defined, cannot convert MSYS " - "paths to Windows paths"); + BAZEL_LOG(ERROR) << "BAZEL_SH environment variable is not defined, " + "cannot convert MSYS paths to Windows paths"; return false; } result = value2; diff --git a/src/main/cpp/util/logging.cc b/src/main/cpp/util/logging.cc index 8ae4b5dbb3..71c9a669f5 100644 --- a/src/main/cpp/util/logging.cc +++ b/src/main/cpp/util/logging.cc @@ -20,6 +20,8 @@ #include #include +#include "src/main/cpp/util/exit_code.h" + namespace blaze_util { const char* LogLevelName(LogLevel level) { @@ -65,17 +67,20 @@ void LogMessage::Finish() { std::string message(message_.str()); if (log_handler_ != nullptr) { log_handler_->HandleMessage(level_, filename_, line_, message); - } else if (level_ == LOGLEVEL_USER) { - // Messages directed at the user should be printed even without a log - // handler. - std::cerr << message << std::endl; - } else if (level_ == LOGLEVEL_FATAL) { - // Expect the log_handler_ to handle FATAL calls, but we should still fail - // as expected even if no log_handler_ is defined. For ease of debugging, - // we also print out the error statement. - std::cerr << filename_ << ":" << line_ << " FATAL: " << message - << std::endl; - std::abort(); + } else { + // If no custom handler was provided, never print INFO messages, + // but USER should always be printed, as should warnings and errors. + if (level_ == LOGLEVEL_USER) { + std::cerr << message << std::endl; + } else if (level_ > LOGLEVEL_USER) { + std::cerr << LogLevelName(level_) << ": " << message << std::endl; + } + + if (level_ == LOGLEVEL_FATAL) { + // Exit for fatal calls after handling the message. + // TODO(b/32967056) pass correct exit code information. + std::exit(blaze_exit_code::INTERNAL_ERROR); + } } } diff --git a/src/test/cpp/util/logging_test.cc b/src/test/cpp/util/logging_test.cc index 94be1f91dc..ae65e7b3fb 100644 --- a/src/test/cpp/util/logging_test.cc +++ b/src/test/cpp/util/logging_test.cc @@ -41,7 +41,71 @@ class LoggingTest : public ::testing::Test { } }; -TEST(LoggingTest, BazelLogHandlerDumpsToCerrAtFail) { +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 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( @@ -63,15 +127,10 @@ TEST(LoggingTest, BazelLogHandlerDumpsToCerrAtFail) { EXPECT_THAT(stderr_output, HasSubstr(teststring)); } -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 the BazelLogHandler, deactivated by +// SetLoggingOutputStream(nullptr). -TEST(LoggingTest, BazelLogDoesNotDumpToStderrIfOuputStreamSetToNull) { +TEST(LoggingTest, BazelLogHandler_DoesNotDumpToStderrIfOuputStreamSetToNull) { // Set up logging and be prepared to capture stderr at destruction. testing::internal::CaptureStderr(); std::unique_ptr handler( @@ -89,7 +148,67 @@ TEST(LoggingTest, BazelLogDoesNotDumpToStderrIfOuputStreamSetToNull) { EXPECT_THAT(stderr_output, Not(HasSubstr(teststring))); } -TEST(LoggingTest, DirectLogsToBufferStreamWorks) { +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 stderr_output = testing::internal::GetCapturedStderr(); + EXPECT_THAT(stderr_output, HasSubstr("WARNING: this is a warning")); +} + +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 stderr_output = testing::internal::GetCapturedStderr(); + EXPECT_THAT(stderr_output, HasSubstr("ERROR: this is an error, alert!\n")); +} + +// 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( @@ -114,7 +233,7 @@ TEST(LoggingTest, DirectLogsToBufferStreamWorks) { EXPECT_THAT(stderr_output, Not(HasSubstr(teststring))); } -TEST(LoggingTest, BufferedLogsSentToSpecifiedStream) { +TEST(LoggingTest, BazelLogHandler_BufferedLogsSentToSpecifiedStream) { // Set up logging and be prepared to capture stderr at destruction. testing::internal::CaptureStderr(); std::unique_ptr handler( @@ -138,54 +257,66 @@ TEST(LoggingTest, BufferedLogsSentToSpecifiedStream) { // Check that the buffered logs were sent. std::string output(stringbuf_ptr->str()); - EXPECT_THAT(output, HasSubstr(teststring)); + EXPECT_THAT(output, + MatchesRegex(".bazel 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, DirectLogsToCerrWorks) { +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 stderr - blaze_util::SetLoggingOutputStreamToStderr(); + // 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)); - // Log something. - std::string teststring = "test that the log messages get directed to cerr"; - BAZEL_LOG(INFO) << teststring; + std::string teststring = "test warning"; + BAZEL_LOG(WARNING) << teststring; - // Cause the logs to be flushed, and capture them. - blaze_util::SetLogHandler(nullptr); + // Check that output went to the buffer. + std::string output(stringbuf_ptr->str()); + EXPECT_THAT(output, MatchesRegex(".bazel WARNING.* test warning\n")); + + // Check that the output never went to stderr. std::string stderr_output = testing::internal::GetCapturedStderr(); - EXPECT_THAT(stderr_output, HasSubstr(teststring)); + EXPECT_THAT(stderr_output, Not(HasSubstr(teststring))); } -TEST(LoggingTest, BufferedLogsGetDirectedToCerr) { +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)); - // 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 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)); - // Ask that the logs get output to stderr - blaze_util::SetLoggingOutputStreamToStderr(); + std::string teststring = "test error"; + BAZEL_LOG(ERROR) << teststring; - // Cause the logs to be flushed, and capture them. - blaze_util::SetLogHandler(nullptr); + // Check that output went to the buffer. + std::string output(stringbuf_ptr->str()); + EXPECT_THAT(output, MatchesRegex(".bazel ERROR.* test error\n")); + + // Check that the output never went to stderr. std::string stderr_output = testing::internal::GetCapturedStderr(); - EXPECT_THAT(stderr_output, HasSubstr(teststring)); + EXPECT_THAT(stderr_output, Not(HasSubstr(teststring))); } -TEST(LoggingTest, ImpossibleFile) { +TEST(LoggingTest, BazelLogHandler_ImpossibleFile) { // Set up logging and be prepared to capture stderr at destruction. testing::internal::CaptureStderr(); std::unique_ptr handler( @@ -203,4 +334,47 @@ TEST(LoggingTest, ImpossibleFile) { EXPECT_THAT(stderr_output, MatchesRegex(".bazel 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; + + // Cause the logs to be flushed, and 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(); + + // Cause the logs to be flushed, and capture them. + blaze_util::SetLogHandler(nullptr); + std::string stderr_output = testing::internal::GetCapturedStderr(); + EXPECT_THAT(stderr_output, HasSubstr(teststring)); +} + } // namespace blaze_util diff --git a/src/test/shell/bazel/testdata/embedded_tools_srcs_deps b/src/test/shell/bazel/testdata/embedded_tools_srcs_deps index 6bc26742d5..47f15a1d2f 100644 --- a/src/test/shell/bazel/testdata/embedded_tools_srcs_deps +++ b/src/test/shell/bazel/testdata/embedded_tools_srcs_deps @@ -37,3 +37,4 @@ //src/main/cpp/util:errors //src/main/cpp/util:port //src/main/cpp/util:blaze_exit_code +//src/main/cpp/util:logging diff --git a/src/test/shell/integration/client_test.sh b/src/test/shell/integration/client_test.sh index 24b04255ed..4717883a70 100755 --- a/src/test/shell/integration/client_test.sh +++ b/src/test/shell/integration/client_test.sh @@ -42,103 +42,112 @@ function test_client_debug() { } function test_client_debug_change_does_not_restart_server() { - PID1=$(bazel --client_debug info server_pid) - PID2=$(bazel info server_pid) - if [[ $PID1 != $PID2 ]]; then - fail "Server restarted due to change in --client_debug" - fi + local server_pid1=$(bazel --client_debug info server_pid 2>$TEST_log) + local server_pid2=$(bazel info server_pid 2>$TEST_log) + assert_equals "$server_pid1" "$server_pid2" + expect_not_log "WARNING: Running B\\(azel\\|laze\\) server needs to be killed" +} + +function test_server_restart_due_to_startup_options() { + local server_pid1=$(bazel --write_command_log info server_pid 2>$TEST_log) + local server_pid2=$(bazel --nowrite_command_log info server_pid 2>$TEST_log) + assert_not_equals "$server_pid1" "$server_pid2" # pid changed. + expect_log "WARNING: Running B\\(azel\\|laze\\) server needs to be killed" } function test_multiple_requests_same_server() { - local server_pid1=$(bazel info server_pid 2>$TEST_log) - local server_pid2=$(bazel info server_pid 2>$TEST_log) - assert_equals "$server_pid1" "$server_pid2" + local server_pid1=$(bazel info server_pid 2>$TEST_log) + local server_pid2=$(bazel info server_pid 2>$TEST_log) + assert_equals "$server_pid1" "$server_pid2" + expect_not_log "WARNING: Running B\\(azel\\|laze\\) server needs to be killed" } function test_shutdown() { - local server_pid1=$(bazel info server_pid 2>$TEST_log) - bazel shutdown >& $TEST_log || fail "Expected success" - local server_pid2=$(bazel info server_pid 2>$TEST_log) - assert_not_equals "$server_pid1" "$server_pid2" + local server_pid1=$(bazel info server_pid 2>$TEST_log) + bazel shutdown >& $TEST_log || fail "Expected success" + local server_pid2=$(bazel info server_pid 2>$TEST_log) + assert_not_equals "$server_pid1" "$server_pid2" } function test_exit_code() { - bazel query not_a_query >/dev/null &>$TEST_log && - fail "bazel query: expected nonzero exit" - expect_log "'not_a_query'" + bazel query not_a_query >/dev/null &>$TEST_log && + fail "bazel query: expected nonzero exit" + expect_log "'not_a_query'" } function test_output_base() { - out=$(bazel --output_base=$TEST_TMPDIR/output info output_base 2>$TEST_log) - assert_equals $TEST_TMPDIR/output "$out" + out=$(bazel --output_base=$TEST_TMPDIR/output info output_base 2>$TEST_log) + assert_equals $TEST_TMPDIR/output "$out" } function test_output_base_is_file() { - bazel --output_base=/dev/null &>$TEST_log && fail "Expected non-zero exit" - expect_log "Error: Output base directory '/dev/null' could not be created.*exists" + bazel --output_base=/dev/null &>$TEST_log && fail "Expected non-zero exit" + expect_log "Error: Output base directory '/dev/null' could not be created.*exists" } function test_cannot_create_output_base() { - bazel --output_base=/foo &>$TEST_log && fail "Expected non-zero exit" - expect_log "Error: Output base directory '/foo' could not be created" + bazel --output_base=/foo &>$TEST_log && fail "Expected non-zero exit" + expect_log "Error: Output base directory '/foo' could not be created" } function test_nonwritable_output_base() { - bazel --output_base=/ &>$TEST_log && fail "Expected non-zero exit" - expect_log "Output base directory '/' must be readable and writable." + bazel --output_base=/ &>$TEST_log && fail "Expected non-zero exit" + expect_log "Output base directory '/' must be readable and writable." } function test_no_arguments() { - bazel >&$TEST_log || fail "Expected zero exit" - expect_log "Usage: b\\(laze\\|azel\\)" + bazel >&$TEST_log || fail "Expected zero exit" + expect_log "Usage: b\\(laze\\|azel\\)" } function test_max_idle_secs() { - local server_pid1=$(bazel --max_idle_secs=1 info server_pid 2>$TEST_log) - sleep 5 - local server_pid2=$(bazel info server_pid 2>$TEST_log) - assert_not_equals "$server_pid1" "$server_pid2" # pid changed. + local server_pid1=$(bazel --max_idle_secs=1 info server_pid 2>$TEST_log) + sleep 5 + local server_pid2=$(bazel info server_pid 2>$TEST_log) + assert_not_equals "$server_pid1" "$server_pid2" # pid changed. + expect_not_log "WARNING: Running B\\(azel\\|laze\\) server needs to be killed" } function test_dashdash_before_command() { - bazel -- info &>$TEST_log && "Expected failure" - exitcode=$? - assert_equals 2 $exitcode - expect_log "Unknown startup option: '--'." + bazel -- info &>$TEST_log && "Expected failure" + exitcode=$? + assert_equals 2 $exitcode + expect_log "Unknown startup option: '--'." } function test_dashdash_after_command() { - bazel info -- &>$TEST_log || fail "info -- failed" + bazel info -- &>$TEST_log || fail "info -- failed" } function test_nobatch() { - local pid1=$(bazel --batch --nobatch info server_pid 2> $TEST_log) - local pid2=$(bazel --batch --nobatch info server_pid 2> $TEST_log) - assert_equals "$pid1" "$pid2" + local pid1=$(bazel --batch --nobatch info server_pid 2> $TEST_log) + local pid2=$(bazel --batch --nobatch info server_pid 2> $TEST_log) + assert_equals "$pid1" "$pid2" + expect_not_log "WARNING: Running B\\(azel\\|laze\\) server needs to be killed" } # Regression test for #1875189, "bazel client should pass through '--help' like # a command". function test_bazel_dash_dash_help_is_passed_through() { - bazel --help >&$TEST_log - expect_log "Usage: b\\(azel\\|laze\\) ..." - expect_not_log "Unknown startup option: '--help'." + bazel --help >&$TEST_log + expect_log "Usage: b\\(azel\\|laze\\) ..." + expect_not_log "Unknown startup option: '--help'." } function test_bazel_dash_help() { - bazel -help >&$TEST_log - expect_log "Usage: b\\(azel\\|laze\\) ..." + bazel -help >&$TEST_log + expect_log "Usage: b\\(azel\\|laze\\) ..." } function test_bazel_dash_h() { - bazel -h >&$TEST_log - expect_log "Usage: b\\(azel\\|laze\\) ..." + bazel -h >&$TEST_log + expect_log "Usage: b\\(azel\\|laze\\) ..." } function test_bazel_dash_s_is_not_parsed() { - bazel -s --help >&$TEST_log && fail "Expected failure" - expect_log "Unknown startup option: '-s'." + bazel -s --help >&$TEST_log && fail "Expected failure" + expect_log "Unknown startup option: '-s'." } function test_cmdline_not_written_in_batch_mode() { -- cgit v1.2.3