folly/experimental/logging/LoggerDB.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/LoggerDB.h>
  17
  18 #include <set>
  19
  20 #include <folly/Conv.h>
  21 #include <folly/FileUtil.h>
  22 #include <folly/String.h>
  23 #include <folly/experimental/logging/LogCategory.h>
  24 #include <folly/experimental/logging/LogConfig.h>
  25 #include <folly/experimental/logging/LogHandler.h>
  26 #include <folly/experimental/logging/LogHandlerFactory.h>
  27 #include <folly/experimental/logging/LogLevel.h>
  28 #include <folly/experimental/logging/Logger.h>
  29 #include <folly/experimental/logging/RateLimiter.h>
  30
  31 using std::string;
  32
  33 namespace folly {
  34
  35 namespace {
  36 class LoggerDBSingleton {
  37  public:
  38   explicit LoggerDBSingleton(LoggerDB* db) : db_{db} {}
  39   ~LoggerDBSingleton() {
  40     // We intentionally leak the LoggerDB object on destruction.
  41     // We want Logger objects to remain valid for the entire lifetime of the
  42     // program, without having to worry about destruction ordering issues, or
  43     // making the Logger perform reference counting on the LoggerDB.
  44     //
  45     // Therefore the main LoggerDB object, and all of the LogCategory objects
  46     // it contains, are always intentionally leaked.
  47     //
  48     // However, we do call db_->cleanupHandlers() to destroy any registered
  49     // LogHandler objects.  The LogHandlers can be user-defined objects and may
  50     // hold resources that should be cleaned up.  This also ensures that the
  51     // LogHandlers flush all outstanding messages before we exit.
  52     db_->cleanupHandlers();
  53   }
  54
  55   LoggerDB* getDB() const {
  56     return db_;
  57   }
  58
  59  private:
  60   LoggerDB* db_;
  61 };
  62 } // namespace
  63
  64 LoggerDB* LoggerDB::get() {
  65   // Intentionally leaky singleton
  66   static LoggerDBSingleton singleton{new LoggerDB()};
  67   return singleton.getDB();
  68 }
  69
  70 LoggerDB::LoggerDB() {
  71   // Create the root log category, and set the level to ERR by default
  72   auto rootUptr = std::make_unique<LogCategory>(this);
  73   LogCategory* root = rootUptr.get();
  74   auto ret =
  75       loggersByName_.wlock()->emplace(root->getName(), std::move(rootUptr));
  76   DCHECK(ret.second);
  77
  78   root->setLevelLocked(LogLevel::ERR, false);
  79 }
  80
  81 LoggerDB::LoggerDB(TestConstructorArg) : LoggerDB() {}
  82
  83 LoggerDB::~LoggerDB() {}
  84
  85 LogCategory* LoggerDB::getCategory(StringPiece name) {
  86   return getOrCreateCategoryLocked(*loggersByName_.wlock(), name);
  87 }
  88
  89 LogCategory* FOLLY_NULLABLE LoggerDB::getCategoryOrNull(StringPiece name) {
  90   auto loggersByName = loggersByName_.rlock();
  91
  92   auto it = loggersByName->find(name);
  93   if (it == loggersByName->end()) {
  94     return nullptr;
  95   }
  96   return it->second.get();
  97 }
  98
  99 void LoggerDB::setLevel(folly::StringPiece name, LogLevel level, bool inherit) {
 100   auto loggersByName = loggersByName_.wlock();
 101   LogCategory* category = getOrCreateCategoryLocked(*loggersByName, name);
 102   category->setLevelLocked(level, inherit);
 103 }
 104
 105 void LoggerDB::setLevel(LogCategory* category, LogLevel level, bool inherit) {
 106   auto loggersByName = loggersByName_.wlock();
 107   category->setLevelLocked(level, inherit);
 108 }
 109
 110 std::vector<std::string> LoggerDB::processConfigString(
 111     folly::StringPiece config) {
 112   std::vector<std::string> errors;
 113   if (config.empty()) {
 114     return errors;
 115   }
 116
 117   std::vector<StringPiece> pieces;
 118   folly::split(",", config, pieces);
 119   for (const auto& p : pieces) {
 120     auto idx = p.rfind('=');
 121     if (idx == folly::StringPiece::npos) {
 122       errors.emplace_back(
 123           folly::sformat("missing '=' in logger configuration: \"{}\"", p));
 124       continue;
 125     }
 126
 127     auto category = p.subpiece(0, idx);
 128     auto level_str = p.subpiece(idx + 1);
 129     LogLevel level;
 130     try {
 131       level = stringToLogLevel(level_str);
 132     } catch (const std::exception&) {
 133       errors.emplace_back(folly::sformat(
 134           "invalid log level \"{}\" for category \"{}\"", level_str, category));
 135       continue;
 136     }
 137
 138     setLevel(category, level);
 139   }
 140
 141   return errors;
 142 }
 143
 144 LogConfig LoggerDB::getConfig() const {
 145   auto handlerInfo = handlerInfo_.rlock();
 146
 147   LogConfig::HandlerConfigMap handlerConfigs;
 148   std::unordered_map<std::shared_ptr<LogHandler>, string> handlersToName;
 149   for (const auto& entry : handlerInfo->handlers) {
 150     auto handler = entry.second.lock();
 151     if (!handler) {
 152       continue;
 153     }
 154     handlersToName.emplace(handler, entry.first);
 155     handlerConfigs.emplace(entry.first, handler->getConfig());
 156   }
 157
 158   size_t anonymousNameIndex = 1;
 159   auto generateAnonymousHandlerName = [&]() {
 160     // Return a unique name of the form "anonymousHandlerN"
 161     // Keep incrementing N until we find a name that isn't currently taken.
 162     while (true) {
 163       auto name = to<string>("anonymousHandler", anonymousNameIndex);
 164       ++anonymousNameIndex;
 165       if (handlerInfo->handlers.find(name) == handlerInfo->handlers.end()) {
 166         return name;
 167       }
 168     }
 169   };
 170
 171   LogConfig::CategoryConfigMap categoryConfigs;
 172   {
 173     auto loggersByName = loggersByName_.rlock();
 174     for (const auto& entry : *loggersByName) {
 175       auto* category = entry.second.get();
 176       auto levelInfo = category->getLevelInfo();
 177       auto handlers = category->getHandlers();
 178
 179       // Don't report categories that have default settings.
 180       if (handlers.empty() && levelInfo.first == LogLevel::MAX_LEVEL &&
 181           levelInfo.second) {
 182         continue;
 183       }
 184
 185       // Translate the handler pointers to names
 186       std::vector<string> handlerNames;
 187       for (const auto& handler : handlers) {
 188         auto iter = handlersToName.find(handler);
 189         if (iter == handlersToName.end()) {
 190           // This LogHandler must have been manually attached to the category,
 191           // rather than defined with `updateConfig()` or `resetConfig()`.
 192           // Generate a unique name to use for reporting it in the config.
 193           auto name = generateAnonymousHandlerName();
 194           handlersToName.emplace(handler, name);
 195           handlerConfigs.emplace(name, handler->getConfig());
 196           handlerNames.emplace_back(name);
 197         } else {
 198           handlerNames.emplace_back(iter->second);
 199         }
 200       }
 201
 202       LogCategoryConfig categoryConfig(
 203           levelInfo.first, levelInfo.second, handlerNames);
 204       categoryConfigs.emplace(category->getName(), std::move(categoryConfig));
 205     }
 206   }
 207
 208   return LogConfig{std::move(handlerConfigs), std::move(categoryConfigs)};
 209 }
 210
 211 LogCategory* LoggerDB::getOrCreateCategoryLocked(
 212     LoggerNameMap& loggersByName,
 213     StringPiece name) {
 214   auto it = loggersByName.find(name);
 215   if (it != loggersByName.end()) {
 216     return it->second.get();
 217   }
 218
 219   StringPiece parentName = LogName::getParent(name);
 220   LogCategory* parent = getOrCreateCategoryLocked(loggersByName, parentName);
 221   return createCategoryLocked(loggersByName, name, parent);
 222 }
 223
 224 LogCategory* LoggerDB::createCategoryLocked(
 225     LoggerNameMap& loggersByName,
 226     StringPiece name,
 227     LogCategory* parent) {
 228   auto uptr = std::make_unique<LogCategory>(name, parent);
 229   LogCategory* logger = uptr.get();
 230   auto ret = loggersByName.emplace(logger->getName(), std::move(uptr));
 231   DCHECK(ret.second);
 232   return logger;
 233 }
 234
 235 void LoggerDB::cleanupHandlers() {
 236   // Get a copy of all categories, so we can call clearHandlers() without
 237   // holding the loggersByName_ lock.  We don't need to worry about LogCategory
 238   // lifetime, since LogCategory objects always live for the lifetime of the
 239   // LoggerDB.
 240   std::vector<LogCategory*> categories;
 241   {
 242     auto loggersByName = loggersByName_.wlock();
 243     categories.reserve(loggersByName->size());
 244     for (const auto& entry : *loggersByName) {
 245       categories.push_back(entry.second.get());
 246     }
 247   }
 248
 249   // Also extract our HandlerFactoryMap and HandlerMap, so we can clear them
 250   // later without holding the handlerInfo_ lock.
 251   HandlerFactoryMap factories;
 252   HandlerMap handlers;
 253   {
 254     auto handlerInfo = handlerInfo_.wlock();
 255     factories.swap(handlerInfo->factories);
 256     handlers.swap(handlerInfo->handlers);
 257   }
 258
 259   // Remove all of the LogHandlers from all log categories,
 260   // to drop any shared_ptr references to the LogHandlers
 261   for (auto* category : categories) {
 262     category->clearHandlers();
 263   }
 264 }
 265
 266 size_t LoggerDB::flushAllHandlers() {
 267   // Build a set of all LogHandlers.  We use a set to avoid calling flush()
 268   // more than once on the same handler if it is registered on multiple
 269   // different categories.
 270   std::set<std::shared_ptr<LogHandler>> handlers;
 271   {
 272     auto loggersByName = loggersByName_.wlock();
 273     for (const auto& entry : *loggersByName) {
 274       for (const auto& handler : entry.second->getHandlers()) {
 275         handlers.emplace(handler);
 276       }
 277     }
 278   }
 279
 280   // Call flush() on each handler
 281   for (const auto& handler : handlers) {
 282     handler->flush();
 283   }
 284   return handlers.size();
 285 }
 286
 287 void LoggerDB::registerHandlerFactory(
 288     std::unique_ptr<LogHandlerFactory> factory,
 289     bool replaceExisting) {
 290   auto type = factory->getType();
 291   auto handlerInfo = handlerInfo_.wlock();
 292   if (replaceExisting) {
 293     handlerInfo->factories[type.str()] = std::move(factory);
 294   } else {
 295     auto ret = handlerInfo->factories.emplace(type.str(), std::move(factory));
 296     if (!ret.second) {
 297       throw std::range_error(to<std::string>(
 298           "a LogHandlerFactory for the type \"", type, "\" already exists"));
 299     }
 300   }
 301 }
 302
 303 void LoggerDB::unregisterHandlerFactory(StringPiece type) {
 304   auto handlerInfo = handlerInfo_.wlock();
 305   auto numRemoved = handlerInfo->factories.erase(type.str());
 306   if (numRemoved != 1) {
 307     throw std::range_error(
 308         to<std::string>("no LogHandlerFactory for type \"", type, "\" found"));
 309   }
 310 }
 311
 312 LogLevel LoggerDB::xlogInit(
 313     StringPiece categoryName,
 314     std::atomic<LogLevel>* xlogCategoryLevel,
 315     LogCategory** xlogCategory) {
 316   // Hold the lock for the duration of the operation
 317   // xlogInit() may be called from multiple threads simultaneously.
 318   // Only one needs to perform the initialization.
 319   auto loggersByName = loggersByName_.wlock();
 320   if (xlogCategory != nullptr && *xlogCategory != nullptr) {
 321     // The xlogCategory was already initialized before we acquired the lock
 322     return (*xlogCategory)->getEffectiveLevel();
 323   }
 324
 325   auto* category = getOrCreateCategoryLocked(*loggersByName, categoryName);
 326   if (xlogCategory) {
 327     // Set *xlogCategory before we update xlogCategoryLevel below.
 328     // This is important, since the XLOG() macros check xlogCategoryLevel to
 329     // tell if *xlogCategory has been initialized yet.
 330     *xlogCategory = category;
 331   }
 332   auto level = category->getEffectiveLevel();
 333   xlogCategoryLevel->store(level, std::memory_order_release);
 334   category->registerXlogLevel(xlogCategoryLevel);
 335   return level;
 336 }
 337
 338 LogCategory* LoggerDB::xlogInitCategory(
 339     StringPiece categoryName,
 340     LogCategory** xlogCategory,
 341     std::atomic<bool>* isInitialized) {
 342   // Hold the lock for the duration of the operation
 343   // xlogInitCategory() may be called from multiple threads simultaneously.
 344   // Only one needs to perform the initialization.
 345   auto loggersByName = loggersByName_.wlock();
 346   if (isInitialized->load(std::memory_order_acquire)) {
 347     // The xlogCategory was already initialized before we acquired the lock
 348     return *xlogCategory;
 349   }
 350
 351   auto* category = getOrCreateCategoryLocked(*loggersByName, categoryName);
 352   *xlogCategory = category;
 353   isInitialized->store(true, std::memory_order_release);
 354   return category;
 355 }
 356
 357 std::atomic<LoggerDB::InternalWarningHandler> LoggerDB::warningHandler_;
 358
 359 void LoggerDB::internalWarningImpl(
 360     folly::StringPiece filename,
 361     int lineNumber,
 362     std::string&& msg) noexcept {
 363   auto handler = warningHandler_.load();
 364   if (handler) {
 365     handler(filename, lineNumber, std::move(msg));
 366   } else {
 367     defaultInternalWarningImpl(filename, lineNumber, std::move(msg));
 368   }
 369 }
 370
 371 void LoggerDB::setInternalWarningHandler(InternalWarningHandler handler) {
 372   // This API is intentionally pretty basic.  It has a number of limitations:
 373   //
 374   // - We only support plain function pointers, and not full std::function
 375   //   objects.  This makes it possible to use std::atomic to access the
 376   //   handler pointer, and also makes it safe to store in a zero-initialized
 377   //   file-static pointer.
 378   //
 379   // - We don't support any void* argument to the handler.  The caller is
 380   //   responsible for storing any callback state themselves.
 381   //
 382   // - When replacing or unsetting a handler we don't make any guarantees about
 383   //   when the old handler will stop being called.  It may still be called
 384   //   from other threads briefly even after setInternalWarningHandler()
 385   //   returns.  This is also a consequence of using std::atomic rather than a
 386   //   full lock.
 387   //
 388   // This provides the minimum capabilities needed to customize the handler,
 389   // while still keeping the implementation simple and safe to use even before
 390   // main().
 391   warningHandler_.store(handler);
 392 }
 393
 394 void LoggerDB::defaultInternalWarningImpl(
 395     folly::StringPiece filename,
 396     int lineNumber,
 397     std::string&& msg) noexcept {
 398   // Rate limit to 10 messages every 5 seconds.
 399   //
 400   // We intentonally use a leaky Meyer's singleton here over folly::Singleton:
 401   // - We want this code to work even before main()
 402   // - This singleton does not depend on any other singletons.
 403   static auto* rateLimiter =
 404       new logging::IntervalRateLimiter{10, std::chrono::seconds(5)};
 405   if (!rateLimiter->check()) {
 406     return;
 407   }
 408
 409   if (folly::kIsDebug) {
 410     // Write directly to file descriptor 2.
 411     //
 412     // It's possible the application has closed fd 2 and is using it for
 413     // something other than stderr.  However we have no good way to detect
 414     // this, which is the main reason we only write to stderr in debug build
 415     // modes.  assert() also writes directly to stderr on failure, which seems
 416     // like a reasonable precedent.
 417     //
 418     // Another option would be to use openlog() and syslog().  However
 419     // calling openlog() may inadvertently affect the behavior of other parts
 420     // of the program also using syslog().
 421     //
 422     // We don't check for write errors here, since there's not much else we can
 423     // do if it fails.
 424     auto fullMsg = folly::to<std::string>(
 425         "logging warning:", filename, ":", lineNumber, ": ", msg, "\n");
 426     folly::writeFull(STDERR_FILENO, fullMsg.data(), fullMsg.size());
 427   }
 428 }
 429 } // namespace folly