logging: add a StandardLogHandlerFactory helper class
[folly.git] / 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 LogConfig LoggerDB::getConfig() const {
111   auto handlerInfo = handlerInfo_.rlock();
112
113   LogConfig::HandlerConfigMap handlerConfigs;
114   std::unordered_map<std::shared_ptr<LogHandler>, string> handlersToName;
115   for (const auto& entry : handlerInfo->handlers) {
116     auto handler = entry.second.lock();
117     if (!handler) {
118       continue;
119     }
120     handlersToName.emplace(handler, entry.first);
121     handlerConfigs.emplace(entry.first, handler->getConfig());
122   }
123
124   size_t anonymousNameIndex = 1;
125   auto generateAnonymousHandlerName = [&]() {
126     // Return a unique name of the form "anonymousHandlerN"
127     // Keep incrementing N until we find a name that isn't currently taken.
128     while (true) {
129       auto name = to<string>("anonymousHandler", anonymousNameIndex);
130       ++anonymousNameIndex;
131       if (handlerInfo->handlers.find(name) == handlerInfo->handlers.end()) {
132         return name;
133       }
134     }
135   };
136
137   LogConfig::CategoryConfigMap categoryConfigs;
138   {
139     auto loggersByName = loggersByName_.rlock();
140     for (const auto& entry : *loggersByName) {
141       auto* category = entry.second.get();
142       auto levelInfo = category->getLevelInfo();
143       auto handlers = category->getHandlers();
144
145       // Don't report categories that have default settings.
146       if (handlers.empty() && levelInfo.first == LogLevel::MAX_LEVEL &&
147           levelInfo.second) {
148         continue;
149       }
150
151       // Translate the handler pointers to names
152       std::vector<string> handlerNames;
153       for (const auto& handler : handlers) {
154         auto iter = handlersToName.find(handler);
155         if (iter == handlersToName.end()) {
156           // This LogHandler must have been manually attached to the category,
157           // rather than defined with `updateConfig()` or `resetConfig()`.
158           // Generate a unique name to use for reporting it in the config.
159           auto name = generateAnonymousHandlerName();
160           handlersToName.emplace(handler, name);
161           handlerConfigs.emplace(name, handler->getConfig());
162           handlerNames.emplace_back(name);
163         } else {
164           handlerNames.emplace_back(iter->second);
165         }
166       }
167
168       LogCategoryConfig categoryConfig(
169           levelInfo.first, levelInfo.second, handlerNames);
170       categoryConfigs.emplace(category->getName(), std::move(categoryConfig));
171     }
172   }
173
174   return LogConfig{std::move(handlerConfigs), std::move(categoryConfigs)};
175 }
176
177 /**
178  * Process handler config information when starting a config update operation.
179  */
180 void LoggerDB::startConfigUpdate(
181     const Synchronized<HandlerInfo>::LockedPtr& handlerInfo,
182     const LogConfig& config,
183     NewHandlerMap* handlers,
184     OldToNewHandlerMap* oldToNewHandlerMap) {
185   // Get a map of all currently existing LogHandlers.
186   // This resolves weak_ptrs to shared_ptrs, and ignores expired weak_ptrs.
187   // This prevents any of these LogHandler pointers from expiring during the
188   // config update.
189   for (const auto& entry : handlerInfo->handlers) {
190     auto handler = entry.second.lock();
191     if (handler) {
192       handlers->emplace(entry.first, std::move(handler));
193     }
194   }
195
196   // Create all of the new LogHandlers needed from this configuration
197   for (const auto& entry : config.getHandlerConfigs()) {
198     // Look up the LogHandlerFactory
199     auto factoryIter = handlerInfo->factories.find(entry.second.type);
200     if (factoryIter == handlerInfo->factories.end()) {
201       throw std::invalid_argument(to<std::string>(
202           "unknown log handler type \"", entry.second.type, "\""));
203     }
204
205     // Check to see if there is an existing LogHandler with this name
206     std::shared_ptr<LogHandler> oldHandler;
207     auto iter = handlers->find(entry.first);
208     if (iter != handlers->end()) {
209       oldHandler = iter->second;
210     }
211
212     // Create the new log handler
213     const auto& factory = factoryIter->second;
214     std::shared_ptr<LogHandler> handler;
215     try {
216       if (oldHandler) {
217         handler = factory->updateHandler(oldHandler, entry.second.options);
218         if (handler != oldHandler) {
219           oldToNewHandlerMap->emplace(oldHandler, handler);
220         }
221       } else {
222         handler = factory->createHandler(entry.second.options);
223       }
224     } catch (const std::exception& ex) {
225       // Errors creating or updating the the log handler are generally due to
226       // bad configuration options.  It is useful to update the exception
227       // message to include the name of the log handler we were trying to
228       // update or create.
229       throw std::invalid_argument(to<string>(
230           "error ",
231           oldHandler ? "updating" : "creating",
232           " log handler \"",
233           entry.first,
234           "\": ",
235           exceptionStr(ex)));
236     }
237     handlerInfo->handlers[entry.first] = handler;
238     (*handlers)[entry.first] = handler;
239   }
240
241   // Before we start making any LogCategory changes, confirm that all handlers
242   // named in the category configs are known handlers.
243   for (const auto& entry : config.getCategoryConfigs()) {
244     if (!entry.second.handlers.hasValue()) {
245       continue;
246     }
247     for (const auto& handlerName : entry.second.handlers.value()) {
248       auto iter = handlers->find(handlerName);
249       if (iter == handlers->end()) {
250         throw std::invalid_argument(to<std::string>(
251             "unknown log handler \"",
252             handlerName,
253             "\" configured for log category \"",
254             entry.first,
255             "\""));
256       }
257     }
258   }
259 }
260
261 /**
262  * Update handlerInfo_ at the end of a config update operation.
263  */
264 void LoggerDB::finishConfigUpdate(
265     const Synchronized<HandlerInfo>::LockedPtr& handlerInfo,
266     NewHandlerMap* handlers,
267     OldToNewHandlerMap* oldToNewHandlerMap) {
268   // Build a new map to replace handlerInfo->handlers
269   // This will contain only the LogHandlers that are still in use by the
270   // current LogCategory settings.
271   std::unordered_map<std::string, std::weak_ptr<LogHandler>> newHandlerMap;
272   for (const auto& entry : *handlers) {
273     newHandlerMap.emplace(entry.first, entry.second);
274   }
275   // Drop all of our shared_ptr references to LogHandler objects,
276   // and then remove entries in newHandlerMap that are unreferenced.
277   handlers->clear();
278   oldToNewHandlerMap->clear();
279   handlerInfo->handlers.clear();
280   for (auto iter = newHandlerMap.begin(); iter != newHandlerMap.end(); /**/) {
281     if (iter->second.expired()) {
282       iter = newHandlerMap.erase(iter);
283     } else {
284       ++iter;
285     }
286   }
287   handlerInfo->handlers.swap(newHandlerMap);
288 }
289
290 std::vector<std::shared_ptr<LogHandler>> LoggerDB::buildCategoryHandlerList(
291     const NewHandlerMap& handlerMap,
292     StringPiece categoryName,
293     const std::vector<std::string>& categoryHandlerNames) {
294   std::vector<std::shared_ptr<LogHandler>> catHandlers;
295   for (const auto& handlerName : categoryHandlerNames) {
296     auto iter = handlerMap.find(handlerName);
297     if (iter == handlerMap.end()) {
298       // This really shouldn't be possible; the checks in startConfigUpdate()
299       // should have already bailed out if there was an unknown handler.
300       throw std::invalid_argument(to<std::string>(
301           "bug: unknown log handler \"",
302           handlerName,
303           "\" configured for log category \"",
304           categoryName,
305           "\""));
306     }
307     catHandlers.push_back(iter->second);
308   }
309
310   return catHandlers;
311 }
312
313 void LoggerDB::updateConfig(const LogConfig& config) {
314   // Grab the handlerInfo_ lock.
315   // We hold it in write mode for the entire config update operation.  This
316   // ensures that only a single config update operation ever runs at once.
317   auto handlerInfo = handlerInfo_.wlock();
318
319   NewHandlerMap handlers;
320   OldToNewHandlerMap oldToNewHandlerMap;
321   startConfigUpdate(handlerInfo, config, &handlers, &oldToNewHandlerMap);
322
323   // If an existing LogHandler was replaced with a new one,
324   // walk all current LogCategories and replace this handler.
325   if (!oldToNewHandlerMap.empty()) {
326     auto loggerMap = loggersByName_.rlock();
327     for (const auto& entry : *loggerMap) {
328       entry.second->updateHandlers(oldToNewHandlerMap);
329     }
330   }
331
332   // Update log levels and handlers mentioned in the config update
333   auto loggersByName = loggersByName_.wlock();
334   for (const auto& entry : config.getCategoryConfigs()) {
335     LogCategory* category =
336         getOrCreateCategoryLocked(*loggersByName, entry.first);
337
338     // Update the log handlers
339     if (entry.second.handlers.hasValue()) {
340       auto catHandlers = buildCategoryHandlerList(
341           handlers, entry.first, entry.second.handlers.value());
342       category->replaceHandlers(std::move(catHandlers));
343     }
344
345     // Update the level settings
346     category->setLevelLocked(
347         entry.second.level, entry.second.inheritParentLevel);
348   }
349
350   finishConfigUpdate(handlerInfo, &handlers, &oldToNewHandlerMap);
351 }
352
353 void LoggerDB::resetConfig(const LogConfig& config) {
354   // Grab the handlerInfo_ lock.
355   // We hold it in write mode for the entire config update operation.  This
356   // ensures that only a single config update operation ever runs at once.
357   auto handlerInfo = handlerInfo_.wlock();
358
359   NewHandlerMap handlers;
360   OldToNewHandlerMap oldToNewHandlerMap;
361   startConfigUpdate(handlerInfo, config, &handlers, &oldToNewHandlerMap);
362
363   // Make sure all log categories mentioned in the new config exist.
364   // This ensures that we will cover them in our walk below.
365   LogCategory* rootCategory;
366   {
367     auto loggersByName = loggersByName_.wlock();
368     rootCategory = getOrCreateCategoryLocked(*loggersByName, "");
369     for (const auto& entry : config.getCategoryConfigs()) {
370       getOrCreateCategoryLocked(*loggersByName, entry.first);
371     }
372   }
373
374   {
375     // Update all log categories
376     auto loggersByName = loggersByName_.rlock();
377     for (const auto& entry : *loggersByName) {
378       auto* category = entry.second.get();
379
380       auto configIter = config.getCategoryConfigs().find(category->getName());
381       if (configIter == config.getCategoryConfigs().end()) {
382         // This category is not listed in the config settings.
383         // Reset it to the default settings.
384         category->clearHandlers();
385
386         if (category == rootCategory) {
387           category->setLevelLocked(LogLevel::ERR, false);
388         } else {
389           category->setLevelLocked(LogLevel::MAX_LEVEL, true);
390         }
391         continue;
392       }
393
394       const auto& catConfig = configIter->second;
395
396       // Update the category log level
397       category->setLevelLocked(catConfig.level, catConfig.inheritParentLevel);
398
399       // Update the category handlers list.
400       // If the handler list is not set in the config, clear out any existing
401       // handlers rather than leaving it as-is.
402       std::vector<std::shared_ptr<LogHandler>> catHandlers;
403       if (catConfig.handlers.hasValue()) {
404         catHandlers = buildCategoryHandlerList(
405             handlers, entry.first, catConfig.handlers.value());
406       }
407       category->replaceHandlers(std::move(catHandlers));
408     }
409   }
410
411   finishConfigUpdate(handlerInfo, &handlers, &oldToNewHandlerMap);
412 }
413
414 LogCategory* LoggerDB::getOrCreateCategoryLocked(
415     LoggerNameMap& loggersByName,
416     StringPiece name) {
417   auto it = loggersByName.find(name);
418   if (it != loggersByName.end()) {
419     return it->second.get();
420   }
421
422   StringPiece parentName = LogName::getParent(name);
423   LogCategory* parent = getOrCreateCategoryLocked(loggersByName, parentName);
424   return createCategoryLocked(loggersByName, name, parent);
425 }
426
427 LogCategory* LoggerDB::createCategoryLocked(
428     LoggerNameMap& loggersByName,
429     StringPiece name,
430     LogCategory* parent) {
431   auto uptr = std::make_unique<LogCategory>(name, parent);
432   LogCategory* logger = uptr.get();
433   auto ret = loggersByName.emplace(logger->getName(), std::move(uptr));
434   DCHECK(ret.second);
435   return logger;
436 }
437
438 void LoggerDB::cleanupHandlers() {
439   // Get a copy of all categories, so we can call clearHandlers() without
440   // holding the loggersByName_ lock.  We don't need to worry about LogCategory
441   // lifetime, since LogCategory objects always live for the lifetime of the
442   // LoggerDB.
443   std::vector<LogCategory*> categories;
444   {
445     auto loggersByName = loggersByName_.wlock();
446     categories.reserve(loggersByName->size());
447     for (const auto& entry : *loggersByName) {
448       categories.push_back(entry.second.get());
449     }
450   }
451
452   // Also extract our HandlerFactoryMap and HandlerMap, so we can clear them
453   // later without holding the handlerInfo_ lock.
454   HandlerFactoryMap factories;
455   HandlerMap handlers;
456   {
457     auto handlerInfo = handlerInfo_.wlock();
458     factories.swap(handlerInfo->factories);
459     handlers.swap(handlerInfo->handlers);
460   }
461
462   // Remove all of the LogHandlers from all log categories,
463   // to drop any shared_ptr references to the LogHandlers
464   for (auto* category : categories) {
465     category->clearHandlers();
466   }
467 }
468
469 size_t LoggerDB::flushAllHandlers() {
470   // Build a set of all LogHandlers.  We use a set to avoid calling flush()
471   // more than once on the same handler if it is registered on multiple
472   // different categories.
473   std::set<std::shared_ptr<LogHandler>> handlers;
474   {
475     auto loggersByName = loggersByName_.wlock();
476     for (const auto& entry : *loggersByName) {
477       for (const auto& handler : entry.second->getHandlers()) {
478         handlers.emplace(handler);
479       }
480     }
481   }
482
483   // Call flush() on each handler
484   for (const auto& handler : handlers) {
485     handler->flush();
486   }
487   return handlers.size();
488 }
489
490 void LoggerDB::registerHandlerFactory(
491     std::unique_ptr<LogHandlerFactory> factory,
492     bool replaceExisting) {
493   auto type = factory->getType();
494   auto handlerInfo = handlerInfo_.wlock();
495   if (replaceExisting) {
496     handlerInfo->factories[type.str()] = std::move(factory);
497   } else {
498     auto ret = handlerInfo->factories.emplace(type.str(), std::move(factory));
499     if (!ret.second) {
500       throw std::range_error(to<std::string>(
501           "a LogHandlerFactory for the type \"", type, "\" already exists"));
502     }
503   }
504 }
505
506 void LoggerDB::unregisterHandlerFactory(StringPiece type) {
507   auto handlerInfo = handlerInfo_.wlock();
508   auto numRemoved = handlerInfo->factories.erase(type.str());
509   if (numRemoved != 1) {
510     throw std::range_error(
511         to<std::string>("no LogHandlerFactory for type \"", type, "\" found"));
512   }
513 }
514
515 LogLevel LoggerDB::xlogInit(
516     StringPiece categoryName,
517     std::atomic<LogLevel>* xlogCategoryLevel,
518     LogCategory** xlogCategory) {
519   // Hold the lock for the duration of the operation
520   // xlogInit() may be called from multiple threads simultaneously.
521   // Only one needs to perform the initialization.
522   auto loggersByName = loggersByName_.wlock();
523   if (xlogCategory != nullptr && *xlogCategory != nullptr) {
524     // The xlogCategory was already initialized before we acquired the lock
525     return (*xlogCategory)->getEffectiveLevel();
526   }
527
528   auto* category = getOrCreateCategoryLocked(*loggersByName, categoryName);
529   if (xlogCategory) {
530     // Set *xlogCategory before we update xlogCategoryLevel below.
531     // This is important, since the XLOG() macros check xlogCategoryLevel to
532     // tell if *xlogCategory has been initialized yet.
533     *xlogCategory = category;
534   }
535   auto level = category->getEffectiveLevel();
536   xlogCategoryLevel->store(level, std::memory_order_release);
537   category->registerXlogLevel(xlogCategoryLevel);
538   return level;
539 }
540
541 LogCategory* LoggerDB::xlogInitCategory(
542     StringPiece categoryName,
543     LogCategory** xlogCategory,
544     std::atomic<bool>* isInitialized) {
545   // Hold the lock for the duration of the operation
546   // xlogInitCategory() may be called from multiple threads simultaneously.
547   // Only one needs to perform the initialization.
548   auto loggersByName = loggersByName_.wlock();
549   if (isInitialized->load(std::memory_order_acquire)) {
550     // The xlogCategory was already initialized before we acquired the lock
551     return *xlogCategory;
552   }
553
554   auto* category = getOrCreateCategoryLocked(*loggersByName, categoryName);
555   *xlogCategory = category;
556   isInitialized->store(true, std::memory_order_release);
557   return category;
558 }
559
560 std::atomic<LoggerDB::InternalWarningHandler> LoggerDB::warningHandler_;
561
562 void LoggerDB::internalWarningImpl(
563     folly::StringPiece filename,
564     int lineNumber,
565     std::string&& msg) noexcept {
566   auto handler = warningHandler_.load();
567   if (handler) {
568     handler(filename, lineNumber, std::move(msg));
569   } else {
570     defaultInternalWarningImpl(filename, lineNumber, std::move(msg));
571   }
572 }
573
574 void LoggerDB::setInternalWarningHandler(InternalWarningHandler handler) {
575   // This API is intentionally pretty basic.  It has a number of limitations:
576   //
577   // - We only support plain function pointers, and not full std::function
578   //   objects.  This makes it possible to use std::atomic to access the
579   //   handler pointer, and also makes it safe to store in a zero-initialized
580   //   file-static pointer.
581   //
582   // - We don't support any void* argument to the handler.  The caller is
583   //   responsible for storing any callback state themselves.
584   //
585   // - When replacing or unsetting a handler we don't make any guarantees about
586   //   when the old handler will stop being called.  It may still be called
587   //   from other threads briefly even after setInternalWarningHandler()
588   //   returns.  This is also a consequence of using std::atomic rather than a
589   //   full lock.
590   //
591   // This provides the minimum capabilities needed to customize the handler,
592   // while still keeping the implementation simple and safe to use even before
593   // main().
594   warningHandler_.store(handler);
595 }
596
597 void LoggerDB::defaultInternalWarningImpl(
598     folly::StringPiece filename,
599     int lineNumber,
600     std::string&& msg) noexcept {
601   // Rate limit to 10 messages every 5 seconds.
602   //
603   // We intentonally use a leaky Meyer's singleton here over folly::Singleton:
604   // - We want this code to work even before main()
605   // - This singleton does not depend on any other singletons.
606   static auto* rateLimiter =
607       new logging::IntervalRateLimiter{10, std::chrono::seconds(5)};
608   if (!rateLimiter->check()) {
609     return;
610   }
611
612   if (folly::kIsDebug) {
613     // Write directly to file descriptor 2.
614     //
615     // It's possible the application has closed fd 2 and is using it for
616     // something other than stderr.  However we have no good way to detect
617     // this, which is the main reason we only write to stderr in debug build
618     // modes.  assert() also writes directly to stderr on failure, which seems
619     // like a reasonable precedent.
620     //
621     // Another option would be to use openlog() and syslog().  However
622     // calling openlog() may inadvertently affect the behavior of other parts
623     // of the program also using syslog().
624     //
625     // We don't check for write errors here, since there's not much else we can
626     // do if it fails.
627     auto fullMsg = folly::to<std::string>(
628         "logging warning:", filename, ":", lineNumber, ": ", msg, "\n");
629     folly::writeFull(STDERR_FILENO, fullMsg.data(), fullMsg.size());
630   }
631 }
632 } // namespace folly