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, ERR, "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::ERR, 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       "arguments: (int: 1234), (char [13]: hello world!)",
 112       messages[0].first.getMessage());
 113   EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
 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   auto expectedLine = __LINE__ + 1;
 123   FB_LOG(logger_, DBG5, "status=", 5, " name=", "foobar");
 124
 125   auto& messages = handler_->getMessages();
 126   ASSERT_EQ(1, messages.size());
 127   EXPECT_EQ("status=5 name=foobar", messages[0].first.getMessage());
 128   EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
 129   EXPECT_EQ(expectedLine, messages[0].first.getLineNumber());
 130   EXPECT_EQ(LogLevel::DBG5, messages[0].first.getLevel());
 131   EXPECT_FALSE(messages[0].first.containsNewlines());
 132   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
 133   EXPECT_EQ(logger_.getCategory(), messages[0].second);
 134 }
 135
 136 class ToStringFailure {};
 137 class FormattableButNoToString {};
 138
 139 [[noreturn]] void toAppend(
 140     const ToStringFailure& /* arg */,
 141     std::string* /* result */) {
 142   throw std::runtime_error(
 143       "error converting ToStringFailure object to a string");
 144 }
 145
 146 namespace folly {
 147 template <>
 148 class FormatValue<ToStringFailure> {
 149  public:
 150   explicit FormatValue(ToStringFailure) {}
 151
 152   template <class FormatCallback>
 153   void format(FormatArg& arg, FormatCallback& cb) const {
 154     FormatValue<std::string>("ToStringFailure").format(arg, cb);
 155   }
 156 };
 157
 158 template <>
 159 class FormatValue<FormattableButNoToString> {
 160  public:
 161   explicit FormatValue(FormattableButNoToString) {}
 162
 163   template <class FormatCallback>
 164   void format(FormatArg&, FormatCallback&) const {
 165     throw std::runtime_error("test");
 166   }
 167 };
 168 } // namespace folly
 169
 170 TEST_F(LoggerTest, toStringError) {
 171   // Use the folly::to<string> log API, with an object that will throw
 172   // an exception when we try to convert it to a string.
 173   //
 174   // The logging code should not throw, but should instead log a message
 175   // with some detail about the failure.
 176   ToStringFailure obj;
 177   auto expectedLine = __LINE__ + 1;
 178   FB_LOG(logger_, DBG1, "status=", obj, " name=", "foobar");
 179
 180   auto& messages = handler_->getMessages();
 181   ASSERT_EQ(1, messages.size());
 182   EXPECT_EQ(
 183       "error constructing log message: "
 184       "error converting ToStringFailure object to a string",
 185       messages[0].first.getMessage());
 186   EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
 187   EXPECT_EQ(expectedLine, messages[0].first.getLineNumber());
 188   EXPECT_EQ(LogLevel::DBG1, messages[0].first.getLevel());
 189   EXPECT_FALSE(messages[0].first.containsNewlines());
 190   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
 191   EXPECT_EQ(logger_.getCategory(), messages[0].second);
 192 }
 193
 194 TEST_F(LoggerTest, formatFallbackError) {
 195   // Check the behavior if logf() fails, and toAppend() also fails.
 196   ToStringFailure obj;
 197   FB_LOGF(logger_, WARN, "param1: {}, param2: {}, {}", 1234, obj);
 198
 199   auto& messages = handler_->getMessages();
 200   ASSERT_EQ(1, messages.size());
 201   EXPECT_EQ(
 202       "error formatting log message: "
 203       "invalid format argument {}: argument index out of range, max=2; "
 204       "format string: \"param1: {}, param2: {}, {}\", "
 205       "arguments: (int: 1234), (ToStringFailure: <error_converting_to_string>)",
 206       messages[0].first.getMessage());
 207   EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
 208   EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel());
 209   EXPECT_FALSE(messages[0].first.containsNewlines());
 210   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
 211   EXPECT_EQ(logger_.getCategory(), messages[0].second);
 212 }
 213
 214 TEST_F(LoggerTest, formatFallbackUnsupported) {
 215   // Check the behavior if logf() fails, and toAppend() also fails.
 216   FormattableButNoToString obj;
 217   FB_LOGF(logger_, WARN, "param1: {}, param2: {}", 1234, obj);
 218
 219   auto& messages = handler_->getMessages();
 220   ASSERT_EQ(1, messages.size());
 221   EXPECT_EQ(
 222       "error formatting log message: "
 223       "test; "
 224       "format string: \"param1: {}, param2: {}\", "
 225       "arguments: (int: 1234), "
 226       "(FormattableButNoToString: <no_string_conversion>)",
 227       messages[0].first.getMessage());
 228   EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
 229   EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel());
 230   EXPECT_FALSE(messages[0].first.containsNewlines());
 231   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
 232   EXPECT_EQ(logger_.getCategory(), messages[0].second);
 233 }
 234
 235 TEST_F(LoggerTest, streamingArgs) {
 236   auto& messages = handler_->getMessages();
 237
 238   // Test with only streaming arguments
 239   std::string foo = "bar";
 240   FB_LOG(logger_, WARN) << "foo=" << foo << ", test=0x" << std::hex << 35;
 241   ASSERT_EQ(1, messages.size());
 242   EXPECT_EQ("foo=bar, test=0x23", messages[0].first.getMessage());
 243   EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
 244   EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel());
 245   EXPECT_FALSE(messages[0].first.containsNewlines());
 246   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
 247   EXPECT_EQ(logger_.getCategory(), messages[0].second);
 248   messages.clear();
 249
 250   // Test with both function-style and streaming arguments
 251   FB_LOG(logger_, WARN, "foo=", foo) << " hello, "
 252                                      << "world: " << 34;
 253   ASSERT_EQ(1, messages.size());
 254   EXPECT_EQ("foo=bar hello, world: 34", messages[0].first.getMessage());
 255   EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
 256   EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel());
 257   EXPECT_FALSE(messages[0].first.containsNewlines());
 258   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
 259   EXPECT_EQ(logger_.getCategory(), messages[0].second);
 260   messages.clear();
 261
 262   // Test with format-style and streaming arguments
 263   FB_LOGF(logger_, WARN, "foo={}, x={}", foo, 34) << ", also " << 12;
 264   ASSERT_EQ(1, messages.size());
 265   EXPECT_EQ("foo=bar, x=34, also 12", messages[0].first.getMessage());
 266   EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
 267   EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel());
 268   EXPECT_FALSE(messages[0].first.containsNewlines());
 269   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
 270   EXPECT_EQ(logger_.getCategory(), messages[0].second);
 271   messages.clear();
 272 }
 273
 274 TEST_F(LoggerTest, escapeSequences) {
 275   // Escape characters (and any other unprintable characters) in the log
 276   // message should be escaped when logged.
 277   auto expectedLine = __LINE__ + 1;
 278   FB_LOG(logger_, WARN, "hello \033[34mworld\033[0m!");
 279
 280   auto& messages = handler_->getMessages();
 281   ASSERT_EQ(1, messages.size());
 282   EXPECT_EQ("hello \\x1b[34mworld\\x1b[0m!", messages[0].first.getMessage());
 283   EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
 284   EXPECT_EQ(expectedLine, messages[0].first.getLineNumber());
 285   EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel());
 286   EXPECT_FALSE(messages[0].first.containsNewlines());
 287   EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
 288   EXPECT_EQ(logger_.getCategory(), messages[0].second);
 289 }
 290
 291 TEST_F(LoggerTest, logMacros) {
 292   Logger foo{&db_, "test.foo.bar"};
 293   Logger foobar{&db_, "test.foo.bar"};
 294   Logger footest{&db_, "test.foo.test"};
 295   Logger footest1234{&db_, "test.foo.test.1234"};
 296   Logger other{&db_, "test.other"};
 297   db_.setLevel("test", LogLevel::ERR);
 298   db_.setLevel("test.foo", LogLevel::DBG2);
 299   db_.setLevel("test.foo.test", LogLevel::DBG7);
 300
 301   auto& messages = handler_->getMessages();
 302
 303   // test.other's effective level should be ERR, so a warning
 304   // message to it should be discarded
 305   FB_LOG(other, WARN, "this should be discarded");
 306   ASSERT_EQ(0, messages.size());
 307
 308   // Disabled log messages should not evaluate their arguments
 309   bool argumentEvaluated = false;
 310   auto getValue = [&] {
 311     argumentEvaluated = true;
 312     return 5;
 313   };
 314   FB_LOG(foobar, DBG3, "discarded message: ", getValue());
 315   EXPECT_FALSE(argumentEvaluated);
 316
 317   FB_LOG(foobar, DBG1, "this message should pass: ", getValue());
 318   ASSERT_EQ(1, messages.size());
 319   EXPECT_EQ("this message should pass: 5", messages[0].first.getMessage());
 320   EXPECT_TRUE(argumentEvaluated);
 321   messages.clear();
 322
 323   // Similar checks with FB_LOGF()
 324   argumentEvaluated = false;
 325   FB_LOGF(footest1234, DBG9, "failing log check: {}", getValue());
 326   EXPECT_FALSE(argumentEvaluated);
 327
 328   FB_LOGF(footest1234, DBG5, "passing log: {:03}", getValue());
 329   ASSERT_EQ(1, messages.size());
 330   EXPECT_EQ("passing log: 005", messages[0].first.getMessage());
 331   EXPECT_TRUE(argumentEvaluated);
 332   messages.clear();
 333
 334   // Bad format arguments should not throw
 335   FB_LOGF(footest1234, ERR, "whoops: {}, {}", getValue());
 336   ASSERT_EQ(1, messages.size());
 337   EXPECT_EQ(
 338       "error formatting log message: "
 339       "invalid format argument {}: argument index out of range, max=1; "
 340       "format string: \"whoops: {}, {}\", "
 341       "arguments: (int: 5)",
 342       messages[0].first.getMessage());
 343   messages.clear();
 344 }