folly/experimental/logging/test/LoggerTest.cpp

   1 /*
   2  * Copyright 2004-present Facebook, Inc.
   3  *
   4  * Licensed under the Apache License, Version 2.0 (the "License");
   5  * you may not use this file except in compliance with the License.
   6  * You may obtain a copy of the License at
   7  *
   8  *   http://www.apache.org/licenses/LICENSE-2.0
   9  *
  10  * Unless required by applicable law or agreed to in writing, software
  11  * distributed under the License is distributed on an "AS IS" BASIS,
  12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  13  * See the License for the specific language governing permissions and
  14  * limitations under the License.
  15  */
  16 #include <folly/experimental/logging/LogCategory.h>
  17 #include <folly/experimental/logging/LogHandler.h>
  18 #include <folly/experimental/logging/LogMessage.h>
  19 #include <folly/experimental/logging/Logger.h>
  20 #include <folly/experimental/logging/LoggerDB.h>
  21 #include <folly/experimental/logging/test/TestLogHandler.h>
  22 #include <folly/portability/GTest.h>
  23
  24 using namespace folly;
  25 using std::make_shared;
  26
  27 class LoggerTest : public ::testing::Test {
  28  protected:
  29   void SetUp() override {
  30     auto* category = logger_.getCategory();
  31
  32     handler_ = make_shared<TestLogHandler>();
  33     category->addHandler(handler_);
  34     category->setLevel(LogLevel::DEBUG, true);
  35   }
  36
  37   LoggerDB db_{LoggerDB::TESTING};
  38   Logger logger_{&db_, "test"};
  39   std::shared_ptr<TestLogHandler> handler_;
  40 };
  41
  42 TEST_F(LoggerTest, basic) {
  43   // Simple log message
  44   logger_.log(LogLevel::WARN, "src/myproject/myfile.cpp", 1234, "hello world");
  45
  46   auto& messages = handler_->getMessages();
  47   ASSERT_EQ(1, messages.size());
  48   EXPECT_EQ("hello world", messages[0].first.getMessage());
  49   EXPECT_EQ("src/myproject/myfile.cpp", messages[0].first.getFileName());
  50   EXPECT_EQ(1234, messages[0].first.getLineNumber());
  51   EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel());
  52   EXPECT_FALSE(messages[0].first.containsNewlines());
  53   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
  54   EXPECT_EQ(logger_.getCategory(), messages[0].second);
  55 }
  56
  57 TEST_F(LoggerTest, subCategory) {
  58   // Log from a sub-category.
  59   Logger subLogger{&db_, "test.foo.bar"};
  60   subLogger.log(LogLevel::ERROR, "myfile.cpp", 99, "sub-category\nlog message");
  61
  62   auto& messages = handler_->getMessages();
  63   ASSERT_EQ(1, messages.size());
  64   EXPECT_EQ("sub-category\nlog message", messages[0].first.getMessage());
  65   EXPECT_EQ("myfile.cpp", messages[0].first.getFileName());
  66   EXPECT_EQ(99, messages[0].first.getLineNumber());
  67   EXPECT_EQ(LogLevel::ERROR, messages[0].first.getLevel());
  68   EXPECT_TRUE(messages[0].first.containsNewlines());
  69   EXPECT_EQ(subLogger.getCategory(), messages[0].first.getCategory());
  70   EXPECT_EQ(logger_.getCategory(), messages[0].second);
  71 }
  72
  73 TEST_F(LoggerTest, formatMessage) {
  74   logger_.logf(
  75       LogLevel::WARN,
  76       "log.cpp",
  77       9,
  78       "num events: {:06d}, duration: {:6.3f}",
  79       1234,
  80       5.6789);
  81
  82   auto& messages = handler_->getMessages();
  83   ASSERT_EQ(1, messages.size());
  84   EXPECT_EQ(
  85       "num events: 001234, duration:  5.679", messages[0].first.getMessage());
  86   EXPECT_EQ("log.cpp", messages[0].first.getFileName());
  87   EXPECT_EQ(9, messages[0].first.getLineNumber());
  88   EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel());
  89   EXPECT_FALSE(messages[0].first.containsNewlines());
  90   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
  91   EXPECT_EQ(logger_.getCategory(), messages[0].second);
  92 }
  93
  94 TEST_F(LoggerTest, follyFormatError) {
  95   // If we pass in a bogus format string, logf() should not throw.
  96   // It should instead log a message, just complaining about the format error.
  97   logger_.logf(
  98       LogLevel::WARN,
  99       "log.cpp",
 100       9,
 101       "param1: {:06d}, param2: {:6.3f}",
 102       1234,
 103       "hello world!");
 104
 105   auto& messages = handler_->getMessages();
 106   ASSERT_EQ(1, messages.size());
 107   EXPECT_EQ(
 108       "error formatting log message: "
 109       "invalid format argument {:6.3f}: invalid specifier 'f'; "
 110       "format string: param1: {:06d}, param2: {:6.3f}",
 111       messages[0].first.getMessage());
 112   EXPECT_EQ("log.cpp", messages[0].first.getFileName());
 113   EXPECT_EQ(9, messages[0].first.getLineNumber());
 114   EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel());
 115   EXPECT_FALSE(messages[0].first.containsNewlines());
 116   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
 117   EXPECT_EQ(logger_.getCategory(), messages[0].second);
 118 }
 119
 120 TEST_F(LoggerTest, toString) {
 121   // Use the log API that calls folly::to<string>
 122   logger_.log(LogLevel::DBG5, "log.cpp", 3, "status=", 5, " name=", "foobar");
 123
 124   auto& messages = handler_->getMessages();
 125   ASSERT_EQ(1, messages.size());
 126   EXPECT_EQ("status=5 name=foobar", messages[0].first.getMessage());
 127   EXPECT_EQ("log.cpp", messages[0].first.getFileName());
 128   EXPECT_EQ(3, messages[0].first.getLineNumber());
 129   EXPECT_EQ(LogLevel::DBG5, messages[0].first.getLevel());
 130   EXPECT_FALSE(messages[0].first.containsNewlines());
 131   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
 132   EXPECT_EQ(logger_.getCategory(), messages[0].second);
 133 }
 134
 135 class ToStringFailure {};
 136
 137 [[noreturn]] void toAppend(
 138     const ToStringFailure& /* arg */,
 139     std::string* /* result */) {
 140   throw std::runtime_error(
 141       "error converting ToStringFailure object to a string");
 142 }
 143
 144 TEST_F(LoggerTest, toStringError) {
 145   // Use the folly::to<string> log API, with an object that will throw
 146   // an exception when we try to convert it to a string.
 147   //
 148   // The logging code should not throw, but should instead log a message
 149   // with some detail about the failure.
 150   ToStringFailure obj;
 151   logger_.log(LogLevel::DBG1, "log.cpp", 3, "status=", obj, " name=", "foobar");
 152
 153   auto& messages = handler_->getMessages();
 154   ASSERT_EQ(1, messages.size());
 155   EXPECT_EQ(
 156       "error constructing log message: "
 157       "error converting ToStringFailure object to a string",
 158       messages[0].first.getMessage());
 159   EXPECT_EQ("log.cpp", messages[0].first.getFileName());
 160   EXPECT_EQ(3, messages[0].first.getLineNumber());
 161   EXPECT_EQ(LogLevel::DBG1, messages[0].first.getLevel());
 162   EXPECT_FALSE(messages[0].first.containsNewlines());
 163   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
 164   EXPECT_EQ(logger_.getCategory(), messages[0].second);
 165 }
 166
 167 TEST_F(LoggerTest, escapeSequences) {
 168   // Escape characters (and any other unprintable characters) in the log
 169   // message should be escaped when logged.
 170   logger_.log(LogLevel::WARN, "termcap.cpp", 34, "hello \033[34mworld\033[0m!");
 171
 172   auto& messages = handler_->getMessages();
 173   ASSERT_EQ(1, messages.size());
 174   EXPECT_EQ("hello \\x1b[34mworld\\x1b[0m!", messages[0].first.getMessage());
 175   EXPECT_EQ("termcap.cpp", messages[0].first.getFileName());
 176   EXPECT_EQ(34, messages[0].first.getLineNumber());
 177   EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel());
 178   EXPECT_FALSE(messages[0].first.containsNewlines());
 179   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
 180   EXPECT_EQ(logger_.getCategory(), messages[0].second);
 181 }
 182
 183 TEST_F(LoggerTest, logMacros) {
 184   Logger foo{&db_, "test.foo.bar"};
 185   Logger foobar{&db_, "test.foo.bar"};
 186   Logger footest{&db_, "test.foo.test"};
 187   Logger footest1234{&db_, "test.foo.test.1234"};
 188   Logger other{&db_, "test.other"};
 189   db_.setLevel("test", LogLevel::ERROR);
 190   db_.setLevel("test.foo", LogLevel::DBG2);
 191   db_.setLevel("test.foo.test", LogLevel::DBG7);
 192
 193   auto& messages = handler_->getMessages();
 194
 195   // test.other's effective level should be ERROR, so a warning
 196   // message to it should be discarded
 197   FB_LOG(other, WARN, "this should be discarded");
 198   ASSERT_EQ(0, messages.size());
 199
 200   // Disabled log messages should not evaluate their arguments
 201   bool argumentEvaluated = false;
 202   auto getValue = [&] {
 203     argumentEvaluated = true;
 204     return 5;
 205   };
 206   FB_LOG(foobar, DBG3, "discarded message: ", getValue());
 207   EXPECT_FALSE(argumentEvaluated);
 208
 209   FB_LOG(foobar, DBG1, "this message should pass: ", getValue());
 210   ASSERT_EQ(1, messages.size());
 211   EXPECT_EQ("this message should pass: 5", messages[0].first.getMessage());
 212   EXPECT_TRUE(argumentEvaluated);
 213   messages.clear();
 214
 215   // Similar checks with FB_LOGF()
 216   argumentEvaluated = false;
 217   FB_LOGF(footest1234, DBG9, "failing log check: {}", getValue());
 218   EXPECT_FALSE(argumentEvaluated);
 219
 220   FB_LOGF(footest1234, DBG5, "passing log: {:03}", getValue());
 221   ASSERT_EQ(1, messages.size());
 222   EXPECT_EQ("passing log: 005", messages[0].first.getMessage());
 223   EXPECT_TRUE(argumentEvaluated);
 224   messages.clear();
 225
 226   // Bad format arguments should not throw
 227   FB_LOGF(footest1234, ERROR, "whoops: {}, {}", getValue());
 228   ASSERT_EQ(1, messages.size());
 229   EXPECT_EQ(
 230       "error formatting log message: "
 231       "invalid format argument {}: argument index out of range, max=1; "
 232       "format string: whoops: {}, {}",
 233       messages[0].first.getMessage());
 234   messages.clear();
 235 }