lldb/unittests/Utility/LogTest.cpp

   1 //===-- LogTest.cpp -------------------------------------------------------===//
   2 //
   3 // Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
   4 // See https://llvm.org/LICENSE.txt for license information.
   5 // SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
   6 //
   7 //===----------------------------------------------------------------------===//
   8
   9 #include "gmock/gmock.h"
  10 #include "gtest/gtest.h"
  11
  12 #include "lldb/Utility/Log.h"
  13 #include "lldb/Utility/StreamString.h"
  14 #include "llvm/ADT/BitmaskEnum.h"
  15 #include "llvm/Support/ManagedStatic.h"
  16 #include "llvm/Support/Threading.h"
  17 #include <thread>
  18
  19 using namespace lldb;
  20 using namespace lldb_private;
  21
  22 enum class TestChannel : Log::MaskType {
  23   FOO = Log::ChannelFlag<0>,
  24   BAR = Log::ChannelFlag<1>,
  25   LLVM_MARK_AS_BITMASK_ENUM(BAR),
  26 };
  27
  28 LLVM_ENABLE_BITMASK_ENUMS_IN_NAMESPACE();
  29
  30 static constexpr Log::Category test_categories[] = {
  31     {{"foo"}, {"log foo"}, TestChannel::FOO},
  32     {{"bar"}, {"log bar"}, TestChannel::BAR},
  33 };
  34
  35 static Log::Channel test_channel(test_categories, TestChannel::FOO);
  36
  37 namespace lldb_private {
  38 template <> Log::Channel &LogChannelFor<TestChannel>() { return test_channel; }
  39 } // namespace lldb_private
  40
  41 // Wrap enable, disable and list functions to make them easier to test.
  42 static bool EnableChannel(std::shared_ptr<LogHandler> log_handler_sp,
  43                           uint32_t log_options, llvm::StringRef channel,
  44                           llvm::ArrayRef<const char *> categories,
  45                           std::string &error) {
  46   error.clear();
  47   llvm::raw_string_ostream error_stream(error);
  48   return Log::EnableLogChannel(log_handler_sp, log_options, channel, categories,
  49                                error_stream);
  50 }
  51
  52 static bool DisableChannel(llvm::StringRef channel,
  53                            llvm::ArrayRef<const char *> categories,
  54                            std::string &error) {
  55   error.clear();
  56   llvm::raw_string_ostream error_stream(error);
  57   return Log::DisableLogChannel(channel, categories, error_stream);
  58 }
  59
  60 static bool ListCategories(llvm::StringRef channel, std::string &result) {
  61   result.clear();
  62   llvm::raw_string_ostream result_stream(result);
  63   return Log::ListChannelCategories(channel, result_stream);
  64 }
  65
  66 namespace {
  67 // A test fixture which provides tests with a pre-registered channel.
  68 struct LogChannelTest : public ::testing::Test {
  69   void TearDown() override { Log::DisableAllLogChannels(); }
  70
  71   static void SetUpTestCase() { Log::Register("chan", test_channel); }
  72
  73   static void TearDownTestCase() {
  74     Log::Unregister("chan");
  75     llvm::llvm_shutdown();
  76   }
  77 };
  78
  79 class TestLogHandler : public LogHandler {
  80 public:
  81   TestLogHandler() : m_messages(), m_stream(m_messages) {}
  82
  83   void Emit(llvm::StringRef message) override { m_stream << message; }
  84
  85   llvm::SmallString<0> m_messages;
  86   llvm::raw_svector_ostream m_stream;
  87 };
  88
  89 // A test fixture which provides tests with a pre-registered and pre-enabled
  90 // channel. Additionally, the messages written to that channel are captured and
  91 // made available via getMessage().
  92 class LogChannelEnabledTest : public LogChannelTest {
  93   std::shared_ptr<TestLogHandler> m_log_handler_sp =
  94       std::make_shared<TestLogHandler>();
  95   Log *m_log;
  96   size_t m_consumed_bytes = 0;
  97
  98 protected:
  99   std::shared_ptr<LogHandler> getLogHandler() { return m_log_handler_sp; }
 100   Log *getLog() { return m_log; }
 101   llvm::StringRef takeOutput();
 102   llvm::StringRef logAndTakeOutput(llvm::StringRef Message);
 103   llvm::StringRef logAndTakeOutputf(llvm::StringRef Message);
 104
 105 public:
 106   void SetUp() override;
 107 };
 108
 109 static std::string GetDumpAsString(const RotatingLogHandler &handler) {
 110   std::string buffer;
 111   llvm::raw_string_ostream stream(buffer);
 112   handler.Dump(stream);
 113   return buffer;
 114 }
 115 } // end anonymous namespace
 116
 117 void LogChannelEnabledTest::SetUp() {
 118   LogChannelTest::SetUp();
 119
 120   std::string error;
 121   ASSERT_TRUE(EnableChannel(m_log_handler_sp, 0, "chan", {}, error));
 122
 123   m_log = GetLog(TestChannel::FOO);
 124   ASSERT_NE(nullptr, m_log);
 125 }
 126
 127 llvm::StringRef LogChannelEnabledTest::takeOutput() {
 128   llvm::StringRef result =
 129       m_log_handler_sp->m_stream.str().drop_front(m_consumed_bytes);
 130   m_consumed_bytes += result.size();
 131   return result;
 132 }
 133
 134 llvm::StringRef
 135 LogChannelEnabledTest::logAndTakeOutput(llvm::StringRef Message) {
 136   LLDB_LOG(m_log, "{0}", Message);
 137   return takeOutput();
 138 }
 139
 140 llvm::StringRef
 141 LogChannelEnabledTest::logAndTakeOutputf(llvm::StringRef Message) {
 142   LLDB_LOGF(m_log, "%s", Message.str().c_str());
 143   return takeOutput();
 144 }
 145
 146 TEST(LogTest, LLDB_LOG_nullptr) {
 147   Log *log = nullptr;
 148   LLDB_LOG(log, "{0}", 0); // Shouldn't crash
 149 }
 150
 151 TEST(LogTest, Register) {
 152   llvm::llvm_shutdown_obj obj;
 153   Log::Register("chan", test_channel);
 154   Log::Unregister("chan");
 155   Log::Register("chan", test_channel);
 156   Log::Unregister("chan");
 157 }
 158
 159 TEST(LogTest, Unregister) {
 160   llvm::llvm_shutdown_obj obj;
 161   Log::Register("chan", test_channel);
 162   EXPECT_EQ(nullptr, GetLog(TestChannel::FOO));
 163   std::string message;
 164   auto log_handler_sp = std::make_shared<TestLogHandler>();
 165   EXPECT_TRUE(
 166       Log::EnableLogChannel(log_handler_sp, 0, "chan", {"foo"}, llvm::nulls()));
 167   EXPECT_NE(nullptr, GetLog(TestChannel::FOO));
 168   Log::Unregister("chan");
 169   EXPECT_EQ(nullptr, GetLog(TestChannel::FOO));
 170 }
 171
 172 namespace {
 173 static char test_baton;
 174 static size_t callback_count = 0;
 175 static void TestCallback(const char *data, void *baton) {
 176   EXPECT_STREQ("Foobar", data);
 177   EXPECT_EQ(&test_baton, baton);
 178   ++callback_count;
 179 }
 180 } // namespace
 181
 182 TEST(LogTest, CallbackLogHandler) {
 183   CallbackLogHandler handler(TestCallback, &test_baton);
 184   handler.Emit("Foobar");
 185   EXPECT_EQ(1u, callback_count);
 186 }
 187
 188 TEST(LogHandlerTest, RotatingLogHandler) {
 189   RotatingLogHandler handler(3);
 190
 191   handler.Emit("foo");
 192   handler.Emit("bar");
 193   EXPECT_EQ(GetDumpAsString(handler), "foobar");
 194
 195   handler.Emit("baz");
 196   handler.Emit("qux");
 197   EXPECT_EQ(GetDumpAsString(handler), "barbazqux");
 198
 199   handler.Emit("quux");
 200   EXPECT_EQ(GetDumpAsString(handler), "bazquxquux");
 201 }
 202
 203 TEST(LogHandlerTest, TeeLogHandler) {
 204   auto handler1 = std::make_shared<RotatingLogHandler>(2);
 205   auto handler2 = std::make_shared<RotatingLogHandler>(2);
 206   TeeLogHandler handler(handler1, handler2);
 207
 208   handler.Emit("foo");
 209   handler.Emit("bar");
 210
 211   EXPECT_EQ(GetDumpAsString(*handler1), "foobar");
 212   EXPECT_EQ(GetDumpAsString(*handler2), "foobar");
 213 }
 214
 215 TEST_F(LogChannelTest, Enable) {
 216   EXPECT_EQ(nullptr, GetLog(TestChannel::FOO));
 217   std::string message;
 218   auto log_handler_sp = std::make_shared<TestLogHandler>();
 219   std::string error;
 220   ASSERT_FALSE(EnableChannel(log_handler_sp, 0, "chanchan", {}, error));
 221   EXPECT_EQ("Invalid log channel 'chanchan'.\n", error);
 222
 223   EXPECT_TRUE(EnableChannel(log_handler_sp, 0, "chan", {}, error));
 224   EXPECT_NE(nullptr, GetLog(TestChannel::FOO));
 225   EXPECT_EQ(nullptr, GetLog(TestChannel::BAR));
 226   EXPECT_NE(nullptr, GetLog(TestChannel::FOO | TestChannel::BAR));
 227
 228   EXPECT_TRUE(EnableChannel(log_handler_sp, 0, "chan", {"bar"}, error));
 229   EXPECT_NE(nullptr, GetLog(TestChannel::FOO));
 230   EXPECT_NE(nullptr, GetLog(TestChannel::BAR));
 231
 232   EXPECT_TRUE(EnableChannel(log_handler_sp, 0, "chan", {"baz"}, error));
 233   EXPECT_NE(std::string::npos, error.find("unrecognized log category 'baz'"))
 234       << "error: " << error;
 235 }
 236
 237 TEST_F(LogChannelTest, EnableOptions) {
 238   EXPECT_EQ(nullptr, GetLog(TestChannel::FOO));
 239   std::string message;
 240   auto log_handler_sp = std::make_shared<TestLogHandler>();
 241   std::string error;
 242   EXPECT_TRUE(EnableChannel(log_handler_sp, LLDB_LOG_OPTION_VERBOSE, "chan", {},
 243                             error));
 244
 245   Log *log = GetLog(TestChannel::FOO);
 246   ASSERT_NE(nullptr, log);
 247   EXPECT_TRUE(log->GetVerbose());
 248 }
 249
 250 TEST_F(LogChannelTest, Disable) {
 251   EXPECT_EQ(nullptr, GetLog(TestChannel::FOO));
 252   std::string message;
 253   auto log_handler_sp = std::make_shared<TestLogHandler>();
 254   std::string error;
 255   EXPECT_TRUE(EnableChannel(log_handler_sp, 0, "chan", {"foo", "bar"}, error));
 256   EXPECT_NE(nullptr, GetLog(TestChannel::FOO));
 257   EXPECT_NE(nullptr, GetLog(TestChannel::BAR));
 258
 259   EXPECT_TRUE(DisableChannel("chan", {"bar"}, error));
 260   EXPECT_NE(nullptr, GetLog(TestChannel::FOO));
 261   EXPECT_EQ(nullptr, GetLog(TestChannel::BAR));
 262
 263   EXPECT_TRUE(DisableChannel("chan", {"baz"}, error));
 264   EXPECT_NE(std::string::npos, error.find("unrecognized log category 'baz'"))
 265       << "error: " << error;
 266   EXPECT_NE(nullptr, GetLog(TestChannel::FOO));
 267   EXPECT_EQ(nullptr, GetLog(TestChannel::BAR));
 268
 269   EXPECT_TRUE(DisableChannel("chan", {}, error));
 270   EXPECT_EQ(nullptr, GetLog(TestChannel::FOO | TestChannel::BAR));
 271 }
 272
 273 TEST_F(LogChannelTest, List) {
 274   std::string list;
 275   EXPECT_TRUE(ListCategories("chan", list));
 276   std::string expected =
 277       R"(Logging categories for 'chan':
 278   all - all available logging categories
 279   default - default set of logging categories
 280   foo - log foo
 281   bar - log bar
 282 )";
 283   EXPECT_EQ(expected, list);
 284
 285   EXPECT_FALSE(ListCategories("chanchan", list));
 286   EXPECT_EQ("Invalid log channel 'chanchan'.\n", list);
 287 }
 288
 289 TEST_F(LogChannelEnabledTest, log_options) {
 290   std::string Err;
 291   EXPECT_EQ("Hello World\n", logAndTakeOutput("Hello World"));
 292   EXPECT_TRUE(EnableChannel(getLogHandler(), 0, "chan", {}, Err));
 293   EXPECT_EQ("Hello World\n", logAndTakeOutput("Hello World"));
 294
 295   {
 296     EXPECT_TRUE(EnableChannel(getLogHandler(), LLDB_LOG_OPTION_PREPEND_SEQUENCE,
 297                               "chan", {}, Err));
 298     llvm::StringRef Msg = logAndTakeOutput("Hello World");
 299     int seq_no;
 300     EXPECT_EQ(1, sscanf(Msg.str().c_str(), "%d Hello World", &seq_no));
 301   }
 302
 303   {
 304     EXPECT_TRUE(EnableChannel(getLogHandler(),
 305                               LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION, "chan", {},
 306                               Err));
 307     llvm::StringRef Msg = logAndTakeOutput("Hello World");
 308     char File[12];
 309     char Function[17];
 310
 311     sscanf(Msg.str().c_str(),
 312            "%[^:]:%s                                 Hello World", File,
 313            Function);
 314     EXPECT_STRCASEEQ("LogTest.cpp", File);
 315     EXPECT_STREQ("logAndTakeOutput", Function);
 316   }
 317
 318   {
 319     EXPECT_TRUE(EnableChannel(getLogHandler(),
 320                               LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION, "chan", {},
 321                               Err));
 322     llvm::StringRef Msg = logAndTakeOutputf("Hello World");
 323     char File[12];
 324     char Function[18];
 325
 326     sscanf(Msg.str().c_str(),
 327            "%[^:]:%s                                 Hello World", File,
 328            Function);
 329     EXPECT_STRCASEEQ("LogTest.cpp", File);
 330     EXPECT_STREQ("logAndTakeOutputf", Function);
 331   }
 332
 333   EXPECT_TRUE(EnableChannel(getLogHandler(),
 334                             LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD, "chan", {},
 335                             Err));
 336   EXPECT_EQ(llvm::formatv("[{0,0+4}/{1,0+4}] Hello World\n", ::getpid(),
 337                           llvm::get_threadid())
 338                 .str(),
 339             logAndTakeOutput("Hello World"));
 340 }
 341
 342 TEST_F(LogChannelEnabledTest, LLDB_LOG_ERROR) {
 343   LLDB_LOG_ERROR(getLog(), llvm::Error::success(), "Foo failed: {0}");
 344   ASSERT_EQ("", takeOutput());
 345
 346   LLDB_LOG_ERROR(getLog(),
 347                  llvm::make_error<llvm::StringError>(
 348                      "My Error", llvm::inconvertibleErrorCode()),
 349                  "Foo failed: {0}");
 350   ASSERT_EQ("Foo failed: My Error\n", takeOutput());
 351
 352   // Doesn't log, but doesn't assert either
 353   LLDB_LOG_ERROR(nullptr,
 354                  llvm::make_error<llvm::StringError>(
 355                      "My Error", llvm::inconvertibleErrorCode()),
 356                  "Foo failed: {0}");
 357 }
 358
 359 TEST_F(LogChannelEnabledTest, LogThread) {
 360   // Test that we are able to concurrently write to a log channel and disable
 361   // it.
 362   std::string err;
 363
 364   // Start logging on one thread. Concurrently, try disabling the log channel.
 365   std::thread log_thread([this] { LLDB_LOG(getLog(), "Hello World"); });
 366   EXPECT_TRUE(DisableChannel("chan", {}, err));
 367   log_thread.join();
 368
 369   // The log thread either managed to write to the log in time, or it didn't. In
 370   // either case, we should not trip any undefined behavior (run the test under
 371   // TSAN to verify this).
 372   EXPECT_THAT(takeOutput(), testing::AnyOf("", "Hello World\n"));
 373 }
 374
 375 TEST_F(LogChannelEnabledTest, LogVerboseThread) {
 376   // Test that we are able to concurrently check the verbose flag of a log
 377   // channel and enable it.
 378   std::string err;
 379
 380   // Start logging on one thread. Concurrently, try enabling the log channel
 381   // (with different log options).
 382   std::thread log_thread([this] { LLDB_LOGV(getLog(), "Hello World"); });
 383   EXPECT_TRUE(
 384       EnableChannel(getLogHandler(), LLDB_LOG_OPTION_VERBOSE, "chan", {}, err));
 385   log_thread.join();
 386
 387   // The log thread either managed to write to the log, or it didn't. In either
 388   // case, we should not trip any undefined behavior (run the test under TSAN to
 389   // verify this).
 390   EXPECT_THAT(takeOutput(), testing::AnyOf("", "Hello World\n"));
 391 }
 392
 393 TEST_F(LogChannelEnabledTest, LogGetLogThread) {
 394   // Test that we are able to concurrently get mask of a Log object and disable
 395   // it.
 396   std::string err;
 397
 398   // Try fetching the log mask on one thread. Concurrently, try disabling the
 399   // log channel.
 400   uint64_t mask;
 401   std::thread log_thread([this, &mask] { mask = getLog()->GetMask(); });
 402   EXPECT_TRUE(DisableChannel("chan", {}, err));
 403   log_thread.join();
 404
 405   // The mask should be either zero of "FOO". In either case, we should not trip
 406   // any undefined behavior (run the test under TSAN to verify this).
 407   EXPECT_THAT(mask, testing::AnyOf(0, Log::MaskType(TestChannel::FOO)));
 408 }