logging: add a LoggerDB::internalWarning() function

Summary:
A few places in the logging code need to report issues when something goes
wrong in the logging code itself.  This adds a new LoggerDB::internalWarning()
method for use in these places.

This provides a default implementation that logs these warnings with
_CrtDbgReport() on Windows, and writes to stderr on non-Windows platforms.
The default implementation can also be overridden for programs that want some
alternative behavior.

Reviewed By: wez

Differential Revision: D5157731

fbshipit-source-id: e27f5587d58b3941fca8d5b38c8c3edbcb75d7f3

folly/experimental/logging/LogCategory.cpp

@@ -71,17 +71,16 @@ void LogCategory::processMessage(const LogMessage& message) const {
     try {
       handlers[n]->handleMessage(message, this);
     } catch (const std::exception& ex) {
-      // If a LogHandler throws an exception, complain about this fact on
-      // stderr to avoid swallowing the error information completely.  We
-      // don't propagate the exception up to our caller: most code does not
-      // prepare for log statements to throw.  We also want to continue
-      // trying to log the message to any other handlers attached to ourself
-      // or one of our parent categories.
-      fprintf(
-          stderr,
-          "WARNING: log handler for category %s threw an error: %s\n",
-          name_.c_str(),
-          folly::exceptionStr(ex).c_str());
+      // Use LoggerDB::internalWarning() to report the error, but continue
+      // trying to log the message to any other handlers attached to ourself or
+      // one of our parent categories.
+      LoggerDB::internalWarning(
+          __FILE__,
+          __LINE__,
+          "log handler for category \"",
+          name_,
+          "\" threw an error: ",
+          folly::exceptionStr(ex));
     }
   }
 

folly/experimental/logging/LoggerDB.cpp

@@ -15,10 +15,17 @@
  */
 #include <folly/experimental/logging/LoggerDB.h>
 
+#if _WIN32
+#include <crtdbg.h>
+#endif
+
+#include <folly/Conv.h>
+#include <folly/FileUtil.h>
 #include <folly/String.h>
 #include <folly/experimental/logging/LogCategory.h>
 #include <folly/experimental/logging/LogLevel.h>
 #include <folly/experimental/logging/Logger.h>
+#include <folly/experimental/logging/RateLimiter.h>
 
 namespace folly {
 
@@ -215,4 +222,83 @@ LogCategory* LoggerDB::xlogInitCategory(
   isInitialized->store(true, std::memory_order_release);
   return category;
 }
+
+std::atomic<LoggerDB::InternalWarningHandler> LoggerDB::warningHandler_;
+
+void LoggerDB::internalWarningImpl(
+    folly::StringPiece filename,
+    int lineNumber,
+    std::string&& msg) noexcept {
+  auto handler = warningHandler_.load();
+  if (handler) {
+    handler(filename, lineNumber, std::move(msg));
+  } else {
+    defaultInternalWarningImpl(filename, lineNumber, std::move(msg));
+  }
+}
+
+void LoggerDB::setInternalWarningHandler(InternalWarningHandler handler) {
+  // This API is intentionally pretty basic.  It has a number of limitations:
+  //
+  // - We only support plain function pointers, and not full std::function
+  //   objects.  This makes it possible to use std::atomic to access the
+  //   handler pointer, and also makes it safe to store in a zero-initialized
+  //   file-static pointer.
+  //
+  // - We don't support any void* argument to the handler.  The caller is
+  //   responsible for storing any callback state themselves.
+  //
+  // - When replacing or unsetting a handler we don't make any guarantees about
+  //   when the old handler will stop being called.  It may still be called
+  //   from other threads briefly even after setInternalWarningHandler()
+  //   returns.  This is also a consequence of using std::atomic rather than a
+  //   full lock.
+  //
+  // This provides the minimum capabilities needed to customize the handler,
+  // while still keeping the implementation simple and safe to use even before
+  // main().
+  warningHandler_.store(handler);
+}
+
+void LoggerDB::defaultInternalWarningImpl(
+    folly::StringPiece filename,
+    int lineNumber,
+    std::string&& msg) noexcept {
+  // Rate limit to 10 messages every 5 seconds.
+  //
+  // We intentonally use a leaky Meyer's singleton here over folly::Singleton:
+  // - We want this code to work even before main()
+  // - This singleton does not depend on any other singletons.
+  static auto* rateLimiter =
+      new logging::IntervalRateLimiter{10, std::chrono::seconds(5)};
+  if (!rateLimiter->check()) {
+    return;
+  }
+
+#if _WIN32
+  // Use _CrtDbgReport() to report the error
+  _CrtDbgReport(
+      _CRT_WARN, filename, lineNumber, "folly::logging", "%s", msg.c_str());
+#else
+  if (folly::kIsDebug) {
+    // Write directly to file descriptor 2.
+    //
+    // It's possible the application has closed fd 2 and is using it for
+    // something other than stderr.  However we have no good way to detect
+    // this, which is the main reason we only write to stderr in debug build
+    // modes.  assert() also writes directly to stderr on failure, which seems
+    // like a reasonable precedent.
+    //
+    // Another option would be to use openlog() and syslog().  However
+    // calling openlog() may inadvertently affect the behavior of other parts
+    // of the program also using syslog().
+    //
+    // We don't check for write errors here, since there's not much else we can
+    // do if it fails.
+    auto fullMsg = folly::to<std::string>(
+        "logging warning:", filename, ":", lineNumber, ": ", msg, "\n");
+    folly::writeFull(STDERR_FILENO, fullMsg.data(), fullMsg.size());
+  }
+#endif
+}
 }

folly/experimental/logging/LoggerDB.h

@@ -15,6 +15,7 @@
  */
 #pragma once
 
+#include <folly/Conv.h>
 #include <folly/CppAttributes.h>
 #include <folly/Range.h>
 #include <folly/Synchronized.h>
@@ -118,6 +119,43 @@ class LoggerDB {
    */
   explicit LoggerDB(TestConstructorArg);
 
+  /**
+   * internalWarning() is used to report a problem when something goes wrong
+   * internally in the logging library.
+   *
+   * We can't log these messages through the normal logging flow since logging
+   * itself has failed.
+   *
+   * Example scenarios where this is used:
+   * - We fail to write to a log file (for instance, when the disk is full)
+   * - A LogHandler throws an unexpected exception
+   */
+  template <typename... Args>
+  static void internalWarning(
+      folly::StringPiece file,
+      int lineNumber,
+      Args&&... args) noexcept {
+    internalWarningImpl(
+        file, lineNumber, folly::to<std::string>(std::forward<Args>(args)...));
+  }
+
+  using InternalWarningHandler =
+      void (*)(folly::StringPiece file, int lineNumber, std::string&&);
+
+  /**
+   * Set a function to be called when the logging library generates an internal
+   * warning.
+   *
+   * The supplied handler should never throw exceptions.
+   *
+   * If a null handler is supplied, the default built-in handler will be used.
+   *
+   * The default handler reports the message with _CrtDbgReport(_CRT_WARN) on
+   * Windows, and prints the message to stderr on other platforms.  It also
+   * rate limits messages if they are arriving too quickly.
+   */
+  static void setInternalWarningHandler(InternalWarningHandler handler);
+
  private:
   using LoggerNameMap = std::unordered_map<
       folly::StringPiece,
@@ -138,6 +176,15 @@ class LoggerDB {
       folly::StringPiece name,
       LogCategory* parent);
 
+  static void internalWarningImpl(
+      folly::StringPiece filename,
+      int lineNumber,
+      std::string&& msg) noexcept;
+  static void defaultInternalWarningImpl(
+      folly::StringPiece filename,
+      int lineNumber,
+      std::string&& msg) noexcept;
+
   /**
    * A map of LogCategory objects by name.
    *
@@ -145,5 +192,7 @@ class LoggerDB {
    * have to be in canonical form.
    */
   folly::Synchronized<LoggerNameMap> loggersByName_;
+
+  static std::atomic<InternalWarningHandler> warningHandler_;
 };
 }