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   static StringPiece pathBasename(StringPiece path) {
  38     auto idx = path.rfind('/');
  39     if (idx == StringPiece::npos) {
  40       return path.str();
  41     }
  42     return path.subpiece(idx + 1);
  43   }
  44
  45   LoggerDB db_{LoggerDB::TESTING};
  46   Logger logger_{&db_, "test"};
  47   std::shared_ptr<TestLogHandler> handler_;
  48 };
  49
  50 TEST_F(LoggerTest, basic) {
  51   // Simple log message
  52   auto expectedLine = __LINE__ + 1;
  53   FB_LOG(logger_, WARN, "hello world");
  54
  55   auto& messages = handler_->getMessages();
  56   ASSERT_EQ(1, messages.size());
  57   EXPECT_EQ("hello world", messages[0].first.getMessage());
  58   EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
  59   EXPECT_EQ(expectedLine, messages[0].first.getLineNumber());
  60   EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel());
  61   EXPECT_FALSE(messages[0].first.containsNewlines());
  62   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
  63   EXPECT_EQ(logger_.getCategory(), messages[0].second);
  64 }
  65
  66 TEST_F(LoggerTest, subCategory) {
  67   // Log from a sub-category.
  68   Logger subLogger{&db_, "test.foo.bar"};
  69   auto expectedLine = __LINE__ + 1;
  70   FB_LOG(subLogger, ERROR, "sub-category\nlog message");
  71
  72   auto& messages = handler_->getMessages();
  73   ASSERT_EQ(1, messages.size());
  74   EXPECT_EQ("sub-category\nlog message", messages[0].first.getMessage());
  75   EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
  76   EXPECT_EQ(expectedLine, messages[0].first.getLineNumber());
  77   EXPECT_EQ(LogLevel::ERROR, messages[0].first.getLevel());
  78   EXPECT_TRUE(messages[0].first.containsNewlines());
  79   EXPECT_EQ(subLogger.getCategory(), messages[0].first.getCategory());
  80   EXPECT_EQ(logger_.getCategory(), messages[0].second);
  81 }
  82
  83 TEST_F(LoggerTest, formatMessage) {
  84   auto expectedLine = __LINE__ + 1;
  85   FB_LOGF(logger_, WARN, "num events: {:06d}, duration: {:6.3f}", 1234, 5.6789);
  86
  87   auto& messages = handler_->getMessages();
  88   ASSERT_EQ(1, messages.size());
  89   EXPECT_EQ(
  90       "num events: 001234, duration:  5.679", messages[0].first.getMessage());
  91   EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
  92   EXPECT_EQ(expectedLine, messages[0].first.getLineNumber());
  93   EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel());
  94   EXPECT_FALSE(messages[0].first.containsNewlines());
  95   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
  96   EXPECT_EQ(logger_.getCategory(), messages[0].second);
  97 }
  98
  99 TEST_F(LoggerTest, follyFormatError) {
 100   // If we pass in a bogus format string, logf() should not throw.
 101   // It should instead log a message, just complaining about the format error.
 102   FB_LOGF(
 103       logger_, WARN, "param1: {:06d}, param2: {:6.3f}", 1234, "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("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
 113   EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel());
 114   EXPECT_FALSE(messages[0].first.containsNewlines());
 115   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
 116   EXPECT_EQ(logger_.getCategory(), messages[0].second);
 117 }
 118
 119 TEST_F(LoggerTest, toString) {
 120   // Use the log API that calls folly::to<string>
 121   auto expectedLine = __LINE__ + 1;
 122   FB_LOG(logger_, DBG5, "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("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
 128   EXPECT_EQ(expectedLine, 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   auto expectedLine = __LINE__ + 1;
 152   FB_LOG(logger_, DBG1, "status=", obj, " name=", "foobar");
 153
 154   auto& messages = handler_->getMessages();
 155   ASSERT_EQ(1, messages.size());
 156   EXPECT_EQ(
 157       "error constructing log message: "
 158       "error converting ToStringFailure object to a string",
 159       messages[0].first.getMessage());
 160   EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
 161   EXPECT_EQ(expectedLine, messages[0].first.getLineNumber());
 162   EXPECT_EQ(LogLevel::DBG1, messages[0].first.getLevel());
 163   EXPECT_FALSE(messages[0].first.containsNewlines());
 164   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
 165   EXPECT_EQ(logger_.getCategory(), messages[0].second);
 166 }
 167
 168 TEST_F(LoggerTest, streamingArgs) {
 169   auto& messages = handler_->getMessages();
 170
 171   // Test with only streaming arguments
 172   std::string foo = "bar";
 173   FB_LOG(logger_, WARN) << "foo=" << foo << ", test=0x" << std::hex << 35;
 174   ASSERT_EQ(1, messages.size());
 175   EXPECT_EQ("foo=bar, test=0x23", messages[0].first.getMessage());
 176   EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
 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   messages.clear();
 182
 183   // Test with both function-style and streaming arguments
 184   FB_LOG(logger_, WARN, "foo=", foo) << " hello, "
 185                                      << "world: " << 34;
 186   ASSERT_EQ(1, messages.size());
 187   EXPECT_EQ("foo=bar hello, world: 34", messages[0].first.getMessage());
 188   EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
 189   EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel());
 190   EXPECT_FALSE(messages[0].first.containsNewlines());
 191   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
 192   EXPECT_EQ(logger_.getCategory(), messages[0].second);
 193   messages.clear();
 194
 195   // Test with format-style and streaming arguments
 196   FB_LOGF(logger_, WARN, "foo={}, x={}", foo, 34) << ", also " << 12;
 197   ASSERT_EQ(1, messages.size());
 198   EXPECT_EQ("foo=bar, x=34, also 12", messages[0].first.getMessage());
 199   EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
 200   EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel());
 201   EXPECT_FALSE(messages[0].first.containsNewlines());
 202   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
 203   EXPECT_EQ(logger_.getCategory(), messages[0].second);
 204   messages.clear();
 205 }
 206
 207 TEST_F(LoggerTest, escapeSequences) {
 208   // Escape characters (and any other unprintable characters) in the log
 209   // message should be escaped when logged.
 210   auto expectedLine = __LINE__ + 1;
 211   FB_LOG(logger_, WARN, "hello \033[34mworld\033[0m!");
 212
 213   auto& messages = handler_->getMessages();
 214   ASSERT_EQ(1, messages.size());
 215   EXPECT_EQ("hello \\x1b[34mworld\\x1b[0m!", messages[0].first.getMessage());
 216   EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
 217   EXPECT_EQ(expectedLine, messages[0].first.getLineNumber());
 218   EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel());
 219   EXPECT_FALSE(messages[0].first.containsNewlines());
 220   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
 221   EXPECT_EQ(logger_.getCategory(), messages[0].second);
 222 }
 223
 224 TEST_F(LoggerTest, logMacros) {
 225   Logger foo{&db_, "test.foo.bar"};
 226   Logger foobar{&db_, "test.foo.bar"};
 227   Logger footest{&db_, "test.foo.test"};
 228   Logger footest1234{&db_, "test.foo.test.1234"};
 229   Logger other{&db_, "test.other"};
 230   db_.setLevel("test", LogLevel::ERROR);
 231   db_.setLevel("test.foo", LogLevel::DBG2);
 232   db_.setLevel("test.foo.test", LogLevel::DBG7);
 233
 234   auto& messages = handler_->getMessages();
 235
 236   // test.other's effective level should be ERROR, so a warning
 237   // message to it should be discarded
 238   FB_LOG(other, WARN, "this should be discarded");
 239   ASSERT_EQ(0, messages.size());
 240
 241   // Disabled log messages should not evaluate their arguments
 242   bool argumentEvaluated = false;
 243   auto getValue = [&] {
 244     argumentEvaluated = true;
 245     return 5;
 246   };
 247   FB_LOG(foobar, DBG3, "discarded message: ", getValue());
 248   EXPECT_FALSE(argumentEvaluated);
 249
 250   FB_LOG(foobar, DBG1, "this message should pass: ", getValue());
 251   ASSERT_EQ(1, messages.size());
 252   EXPECT_EQ("this message should pass: 5", messages[0].first.getMessage());
 253   EXPECT_TRUE(argumentEvaluated);
 254   messages.clear();
 255
 256   // Similar checks with FB_LOGF()
 257   argumentEvaluated = false;
 258   FB_LOGF(footest1234, DBG9, "failing log check: {}", getValue());
 259   EXPECT_FALSE(argumentEvaluated);
 260
 261   FB_LOGF(footest1234, DBG5, "passing log: {:03}", getValue());
 262   ASSERT_EQ(1, messages.size());
 263   EXPECT_EQ("passing log: 005", messages[0].first.getMessage());
 264   EXPECT_TRUE(argumentEvaluated);
 265   messages.clear();
 266
 267   // Bad format arguments should not throw
 268   FB_LOGF(footest1234, ERROR, "whoops: {}, {}", getValue());
 269   ASSERT_EQ(1, messages.size());
 270   EXPECT_EQ(
 271       "error formatting log message: "
 272       "invalid format argument {}: argument index out of range, max=1; "
 273       "format string: \"whoops: {}, {}\"",
 274       messages[0].first.getMessage());
 275   messages.clear();
 276 }