logging_unittest.cc | Explore in Territory

// Copyright 2011 The Chromium Authors
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

#ifdef UNSAFE_BUFFERS_BUILD
// TODO(crbug.com/40284755): Remove this and spanify to fix the errors.
#pragma allow_unsafe_buffers
#endif

#include "base/logging.h"

#include <sstream>
#include <string>
#include <string_view>

#include "base/command_line.h"
#include "base/files/file_util.h"
#include "base/files/scoped_temp_dir.h"
#include "base/functional/bind.h"
#include "base/functional/callback.h"
#include "base/no_destructor.h"
#include "base/process/process.h"
#include "base/run_loop.h"
#include "base/sanitizer_buildflags.h"
#include "base/strings/strcat.h"
#include "base/strings/string_number_conversions.h"
#include "base/strings/utf_string_conversions.h"
#include "base/test/bind.h"
#include "base/test/scoped_logging_settings.h"
#include "base/test/task_environment.h"
#include "build/build_config.h"
#include "build/chromeos_buildflags.h"
#include "testing/gmock/include/gmock/gmock.h"
#include "testing/gtest/include/gtest/gtest.h"

#if BUILDFLAG(IS_POSIX)
#include <errno.h>
#include <signal.h>
#include <unistd.h>

#include "base/posix/eintr_wrapper.h"
#endif  // BUILDFLAG(IS_POSIX)

#if BUILDFLAG(IS_LINUX) || BUILDFLAG(IS_CHROMEOS) || BUILDFLAG(IS_ANDROID)
#include <ucontext.h>
#endif

#if BUILDFLAG(IS_WIN)
#include <windows.h>

#include <excpt.h>
#endif  // BUILDFLAG(IS_WIN)

#if BUILDFLAG(IS_FUCHSIA)
#include <lib/zx/channel.h>
#include <lib/zx/event.h>
#include <lib/zx/exception.h>
#include <lib/zx/thread.h>
#include <zircon/syscalls/debug.h>
#include <zircon/syscalls/exception.h>
#include <zircon/types.h>
#endif  // BUILDFLAG(IS_FUCHSIA)

#include <optional>

namespace logging {

namespace {

Return;
_;

class LoggingTest : public testing::Test { … };

class MockLogSource { … };

class MockLogAssertHandler { … };

TEST_F(LoggingTest, BasicLogging) { … }

TEST_F(LoggingTest, LogIsOn) { … }

TEST_F(LoggingTest, LoggingIsLazyBySeverity) { … }

TEST_F(LoggingTest, LoggingIsLazyByDestination) { … }

// Check that logging to stderr is gated on LOG_TO_STDERR.
TEST_F(LoggingTest, LogToStdErrFlag) { … }

// Check that messages with severity ERROR or higher are always logged to
// stderr if no log-destinations are set, other than LOG_TO_FILE.
// This test is currently only POSIX-compatible.
#if BUILDFLAG(IS_POSIX) || BUILDFLAG(IS_FUCHSIA)
namespace {
void TestForLogToStderr(int log_destinations,
                        bool* did_log_info,
                        bool* did_log_error) { … }
}  // namespace

TEST_F(LoggingTest, AlwaysLogErrorsToStderr) { … }
#endif  // BUILDFLAG(IS_POSIX) || BUILDFLAG(IS_FUCHSIA)

#if BUILDFLAG(IS_CHROMEOS_ASH)
TEST_F(LoggingTest, InitWithFileDescriptor) {
  const char kErrorLogMessage[] = "something bad happened";

  // Open a file to pass to the InitLogging.
  base::ScopedTempDir temp_dir;
  ASSERT_TRUE(temp_dir.CreateUniqueTempDir());
  base::FilePath file_log_path = temp_dir.GetPath().Append("file.log");
  FILE* log_file = fopen(file_log_path.value().c_str(), "w");
  CHECK(log_file);

  // Set up logging.
  LoggingSettings settings;
  settings.logging_dest = LOG_TO_FILE;
  settings.log_file = log_file;
  InitLogging(settings);

  LOG(ERROR) << kErrorLogMessage;

  // Check the message was written to the log file.
  std::string written_logs;
  ASSERT_TRUE(base::ReadFileToString(file_log_path, &written_logs));
  ASSERT_NE(written_logs.find(kErrorLogMessage), std::string::npos);
}

TEST_F(LoggingTest, DuplicateLogFile) {
  const char kErrorLogMessage1[] = "something really bad happened";
  const char kErrorLogMessage2[] = "some other bad thing happened";

  base::ScopedTempDir temp_dir;
  ASSERT_TRUE(temp_dir.CreateUniqueTempDir());
  base::FilePath file_log_path = temp_dir.GetPath().Append("file.log");

  // Set up logging.
  LoggingSettings settings;
  settings.logging_dest = LOG_TO_FILE;
  settings.log_file_path = file_log_path.value().c_str();
  InitLogging(settings);

  LOG(ERROR) << kErrorLogMessage1;

  // Duplicate the log FILE, close the original (to make sure we actually
  // duplicated it), and write to the duplicate.
  FILE* log_file_dup = DuplicateLogFILE();
  CHECK(log_file_dup);
  CloseLogFile();
  fprintf(log_file_dup, "%s\n", kErrorLogMessage2);
  fflush(log_file_dup);

  // Check the messages were written to the log file.
  std::string written_logs;
  ASSERT_TRUE(base::ReadFileToString(file_log_path, &written_logs));
  ASSERT_NE(written_logs.find(kErrorLogMessage1), std::string::npos);
  ASSERT_NE(written_logs.find(kErrorLogMessage2), std::string::npos);
  fclose(log_file_dup);
}
#endif  // BUILDFLAG(IS_CHROMEOS_ASH)

#if !CHECK_WILL_STREAM() && BUILDFLAG(IS_WIN)
NOINLINE void CheckContainingFunc(int death_location) {
  CHECK(death_location != 1);
  CHECK(death_location != 2);
  CHECK(death_location != 3);
}

int GetCheckExceptionData(EXCEPTION_POINTERS* p, DWORD* code, void** addr) {
  *code = p->ExceptionRecord->ExceptionCode;
  *addr = p->ExceptionRecord->ExceptionAddress;
  return EXCEPTION_EXECUTE_HANDLER;
}

TEST_F(LoggingTest, CheckCausesDistinctBreakpoints) {
  DWORD code1 = 0;
  DWORD code2 = 0;
  DWORD code3 = 0;
  void* addr1 = nullptr;
  void* addr2 = nullptr;
  void* addr3 = nullptr;

  // Record the exception code and addresses.
  __try {
    CheckContainingFunc(1);
  } __except (
      GetCheckExceptionData(GetExceptionInformation(), &code1, &addr1)) {
  }

  __try {
    CheckContainingFunc(2);
  } __except (
      GetCheckExceptionData(GetExceptionInformation(), &code2, &addr2)) {
  }

  __try {
    CheckContainingFunc(3);
  } __except (
      GetCheckExceptionData(GetExceptionInformation(), &code3, &addr3)) {
  }

  // Ensure that the exception codes are correct (in particular, breakpoints,
  // not access violations).
  EXPECT_EQ(STATUS_BREAKPOINT, code1);
  EXPECT_EQ(STATUS_BREAKPOINT, code2);
  EXPECT_EQ(STATUS_BREAKPOINT, code3);

  // Ensure that none of the CHECKs are colocated.
  EXPECT_NE(addr1, addr2);
  EXPECT_NE(addr1, addr3);
  EXPECT_NE(addr2, addr3);
}
#elif BUILDFLAG(IS_FUCHSIA)

// CHECK causes a direct crash (without jumping to another function) only in
// official builds. Unfortunately, continuous test coverage on official builds
// is lower. Furthermore, since the Fuchsia implementation uses threads, it is
// not possible to rely on an implementation of CHECK that calls abort(), which
// takes down the whole process, preventing the thread exception handler from
// handling the exception. DO_CHECK here falls back on base::ImmediateCrash() in
// non-official builds, to catch regressions earlier in the CQ.
#if !CHECK_WILL_STREAM()
#define DO_CHECK …
#else
#define DO_CHECK …
#endif

struct thread_data_t {
  // For signaling the thread ended properly.
  zx::event event;
  // For catching thread exceptions. Created by the crashing thread.
  zx::channel channel;
  // Location where the thread is expected to crash.
  int death_location;
};

// Indicates the exception channel has been created successfully.
constexpr zx_signals_t kChannelReadySignal = ZX_USER_SIGNAL_0;

// Indicates an error setting up the crash thread.
constexpr zx_signals_t kCrashThreadErrorSignal = ZX_USER_SIGNAL_1;

void* CrashThread(void* arg) {
  thread_data_t* data = (thread_data_t*)arg;
  int death_location = data->death_location;

  // Register the exception handler.
  zx_status_t status =
      zx::thread::self()->create_exception_channel(0, &data->channel);
  if (status != ZX_OK) {
    data->event.signal(0, kCrashThreadErrorSignal);
    return nullptr;
  }
  data->event.signal(0, kChannelReadySignal);

  DO_CHECK(death_location != 1);
  DO_CHECK(death_location != 2);
  DO_CHECK(death_location != 3);

  // We should never reach this point, signal the thread incorrectly ended
  // properly.
  data->event.signal(0, kCrashThreadErrorSignal);
  return nullptr;
}

// Helper function to call pthread_exit(nullptr).
_Noreturn __NO_SAFESTACK void exception_pthread_exit() {
  pthread_exit(nullptr);
}

// Runs the CrashThread function in a separate thread.
void SpawnCrashThread(int death_location, uintptr_t* child_crash_addr) {
  zx::event event;
  zx_status_t status = zx::event::create(0, &event);
  ASSERT_EQ(status, ZX_OK);

  // Run the thread.
  thread_data_t thread_data = {std::move(event), zx::channel(), death_location};
  pthread_t thread;
  int ret = pthread_create(&thread, nullptr, CrashThread, &thread_data);
  ASSERT_EQ(ret, 0);

  // Wait for the thread to set up its exception channel.
  zx_signals_t signals = 0;
  status =
      thread_data.event.wait_one(kChannelReadySignal | kCrashThreadErrorSignal,
                                 zx::time::infinite(), &signals);
  ASSERT_EQ(status, ZX_OK);
  ASSERT_EQ(signals, kChannelReadySignal);

  // Wait for the exception and read it out of the channel.
  status =
      thread_data.channel.wait_one(ZX_CHANNEL_READABLE | ZX_CHANNEL_PEER_CLOSED,
                                   zx::time::infinite(), &signals);
  ASSERT_EQ(status, ZX_OK);
  // Check the thread did crash and not terminate.
  ASSERT_FALSE(signals & ZX_CHANNEL_PEER_CLOSED);

  zx_exception_info_t exception_info;
  zx::exception exception;
  status = thread_data.channel.read(
      0, &exception_info, exception.reset_and_get_address(),
      sizeof(exception_info), 1, nullptr, nullptr);
  ASSERT_EQ(status, ZX_OK);

  // Get the crash address and point the thread towards exiting.
  zx::thread zircon_thread;
  status = exception.get_thread(&zircon_thread);
  ASSERT_EQ(status, ZX_OK);
  zx_thread_state_general_regs_t buffer;
  status = zircon_thread.read_state(ZX_THREAD_STATE_GENERAL_REGS, &buffer,
                                    sizeof(buffer));
  ASSERT_EQ(status, ZX_OK);
#if defined(ARCH_CPU_X86_64)
  *child_crash_addr = static_cast<uintptr_t>(buffer.rip);
  buffer.rip = reinterpret_cast<uintptr_t>(exception_pthread_exit);
#elif defined(ARCH_CPU_ARM64)
  *child_crash_addr = static_cast<uintptr_t>(buffer.pc);
  buffer.pc = reinterpret_cast<uintptr_t>(exception_pthread_exit);
#else
#error Unsupported architecture
#endif
  ASSERT_EQ(zircon_thread.write_state(ZX_THREAD_STATE_GENERAL_REGS, &buffer,
                                      sizeof(buffer)),
            ZX_OK);

  // Clear the exception so the thread continues.
  uint32_t state = ZX_EXCEPTION_STATE_HANDLED;
  ASSERT_EQ(
      exception.set_property(ZX_PROP_EXCEPTION_STATE, &state, sizeof(state)),
      ZX_OK);
  exception.reset();

  // Join the exiting pthread.
  ASSERT_EQ(pthread_join(thread, nullptr), 0);
}

TEST_F(LoggingTest, CheckCausesDistinctBreakpoints) {
  uintptr_t child_crash_addr_1 = 0;
  uintptr_t child_crash_addr_2 = 0;
  uintptr_t child_crash_addr_3 = 0;

  SpawnCrashThread(1, &child_crash_addr_1);
  SpawnCrashThread(2, &child_crash_addr_2);
  SpawnCrashThread(3, &child_crash_addr_3);

  ASSERT_NE(0u, child_crash_addr_1);
  ASSERT_NE(0u, child_crash_addr_2);
  ASSERT_NE(0u, child_crash_addr_3);
  ASSERT_NE(child_crash_addr_1, child_crash_addr_2);
  ASSERT_NE(child_crash_addr_1, child_crash_addr_3);
  ASSERT_NE(child_crash_addr_2, child_crash_addr_3);
}
#elif BUILDFLAG(IS_POSIX) && !BUILDFLAG(IS_NACL) && !BUILDFLAG(IS_IOS) && \
    (defined(ARCH_CPU_X86_FAMILY) || defined(ARCH_CPU_ARM_FAMILY))

int g_child_crash_pipe;

void CheckCrashTestSighandler(int, siginfo_t* info, void* context_ptr) { … }

// CHECK causes a direct crash (without jumping to another function) only in
// official builds. Unfortunately, continuous test coverage on official builds
// is lower. DO_CHECK here falls back on a home-brewed implementation in
// non-official builds, to catch regressions earlier in the CQ.
#if !CHECK_WILL_STREAM()
#define DO_CHECK …
#else
#define DO_CHECK(cond) …
#endif

void CrashChildMain(int death_location) { … }

void SpawnChildAndCrash(int death_location, uintptr_t* child_crash_addr) { … }

TEST_F(LoggingTest, CheckCausesDistinctBreakpoints) { … }
#endif  // BUILDFLAG(IS_POSIX)

TEST_F(LoggingTest, DebugLoggingReleaseBehavior) { … }

TEST_F(LoggingTest, NestedLogAssertHandlers) { … }

// Test that defining an operator<< for a type in a namespace doesn't prevent
// other code in that namespace from calling the operator<<(ostream, wstring)
// defined by logging.h. This can fail if operator<<(ostream, wstring) can't be
// found by ADL, since defining another operator<< prevents name lookup from
// looking in the global namespace.
namespace nested_test {
  class Streamable { … };
  [[maybe_unused]] std::ostream& operator<<(std::ostream& out,
                                            const Streamable&) { … }
  TEST_F(LoggingTest, StreamingWstringFindsCorrectOperator) { … }
}  // namespace nested_test

TEST_F(LoggingTest, LogPrefix) { … }

#if BUILDFLAG(IS_CHROMEOS_ASH)
TEST_F(LoggingTest, LogCrosSyslogFormat) {
  // Set log format to syslog format.
  scoped_logging_settings().SetLogFormat(LogFormat::LOG_FORMAT_SYSLOG);

  const char* kTimestampPattern = R"(\d\d\d\d\-\d\d\-\d\d)"             // date
                                  R"(T\d\d\:\d\d\:\d\d\.\d\d\d\d\d\d)"  // time
                                  R"(Z.+\n)";  // timezone

  // Use a static because only captureless lambdas can be converted to a
  // function pointer for SetLogMessageHandler().
  static base::NoDestructor<std::string> log_string;
  SetLogMessageHandler([](int severity, const char* file, int line,
                          size_t start, const std::string& str) -> bool {
    *log_string = str;
    return true;
  });

  {
    // All flags are true.
    SetLogItems(true, true, true, true);
    const char* kExpected =
        R"(\S+ \d+ ERROR \S+\[\d+:\d+\]\: \[\S+\] message\n)";

    LOG(ERROR) << "message";

    EXPECT_THAT(*log_string, ::testing::MatchesRegex(kTimestampPattern));
    EXPECT_THAT(*log_string, ::testing::MatchesRegex(kExpected));
  }

  {
    // Timestamp is true.
    SetLogItems(false, false, true, false);
    const char* kExpected = R"(\S+ ERROR \S+\: \[\S+\] message\n)";

    LOG(ERROR) << "message";

    EXPECT_THAT(*log_string, ::testing::MatchesRegex(kTimestampPattern));
    EXPECT_THAT(*log_string, ::testing::MatchesRegex(kExpected));
  }

  {
    // PID and timestamp are true.
    SetLogItems(true, false, true, false);
    const char* kExpected = R"(\S+ ERROR \S+\[\d+\]: \[\S+\] message\n)";

    LOG(ERROR) << "message";

    EXPECT_THAT(*log_string, ::testing::MatchesRegex(kTimestampPattern));
    EXPECT_THAT(*log_string, ::testing::MatchesRegex(kExpected));
  }

  {
    // ThreadID and timestamp are true.
    SetLogItems(false, true, true, false);
    const char* kExpected = R"(\S+ ERROR \S+\[:\d+\]: \[\S+\] message\n)";

    LOG(ERROR) << "message";

    EXPECT_THAT(*log_string, ::testing::MatchesRegex(kTimestampPattern));
    EXPECT_THAT(*log_string, ::testing::MatchesRegex(kExpected));
  }

  {
    // All flags are false.
    SetLogItems(false, false, false, false);
    const char* kExpected = R"(ERROR \S+: \[\S+\] message\n)";

    LOG(ERROR) << "message";

    EXPECT_THAT(*log_string, ::testing::MatchesRegex(kExpected));
  }
}
#endif  // BUILDFLAG(IS_CHROMEOS_ASH)

// We define a custom operator<< for std::u16string so we can use it with
// logging. This tests that conversion.
TEST_F(LoggingTest, String16) { … }

// Tests that we don't VLOG from logging_unittest except when in the scope
// of the ScopedVmoduleSwitches.
TEST_F(LoggingTest, ScopedVmoduleSwitches) { … }

TEST_F(LoggingTest, BuildCrashString) { … }

TEST_F(LoggingTest, SystemErrorNotChanged) { … }

TEST_F(LoggingTest, CorrectSystemErrorUsed) { … }

TEST_F(LoggingTest, BuildTimeVLOG) { … }

// NO NEW TESTS HERE
// The test above redefines ENABLED_VLOG_LEVEL, so new tests should be added
// before it.

}  // namespace

}  // namespace logging
chromium/base/logging_unittest.cc
