logging: if folly::format() fails, also log the arguments

Summary:
If the folly::sformat() call fails in an FB_LOGF() statement, make a
best-effort attempt to log the format arguments as well, in addition to the
format string.  For each argument, folly::to<std::string>() is use if it is
supported for this argument.

This will help ensure that the arguments that were being logged aren't lost
even if the format string was incorrect.

Reviewed By: WillerZ

Differential Revision: D5082978

fbshipit-source-id: 0d56030e639cd7e8f2242bb43646ab4248c6a877

diff --git a/folly/experimental/logging/LogStreamProcessor.h b/folly/experimental/logging/LogStreamProcessor.h
index b68de952bea47e5e84bb9b67a1ab28b6b34117e2..f95e00e44e6168da5422bba255fee363a917441d 100644 (file)
--- a/folly/experimental/logging/LogStreamProcessor.h
+++ b/folly/experimental/logging/LogStreamProcessor.h
@@ -16,6 +16,7 @@
 #pragma once
 
 #include <folly/Conv.h>
+#include <folly/Demangle.h>
 #include <folly/Format.h>
 #include <folly/experimental/logging/LogCategory.h>
 #include <folly/experimental/logging/LogMessage.h>
@@ -24,6 +25,49 @@ namespace folly {
 
 class LogStream;
 
+/*
+ * Helper functions for fallback-formatting of arguments if folly::format()
+ * throws an exception.
+ *
+ * These are in a detail namespace so that we can include a using directive in
+ * order to do proper argument-dependent lookup of the correct toAppend()
+ * function to use.
+ */
+namespace detail {
+/* using override */
+using folly::toAppend;
+template <typename Arg>
+auto fallbackFormatOneArg(std::string* str, const Arg* arg, int) -> decltype(
+    toAppend(std::declval<Arg>(), std::declval<std::string*>()),
+    std::declval<void>()) {
+  str->push_back('(');
+  try {
+#ifdef FOLLY_HAS_RTTI
+    toAppend(folly::demangle(typeid(*arg)), str);
+    str->append(": ");
+#endif
+    toAppend(*arg, str);
+  } catch (const std::exception&) {
+    str->append("<error_converting_to_string>");
+  }
+  str->push_back(')');
+}
+
+template <typename Arg>
+inline void fallbackFormatOneArg(std::string* str, const Arg* arg, long) {
+  str->push_back('(');
+#ifdef FOLLY_HAS_RTTI
+  try {
+    toAppend(folly::demangle(typeid(*arg)), str);
+    str->append(": ");
+  } catch (const std::exception&) {
+    // Ignore the error
+  }
+#endif
+  str->append("<no_string_conversion>)");
+}
+}
+
 /**
  * LogStreamProcessor receives a LogStream and logs it.
  *
@@ -159,26 +203,50 @@ class LogStreamProcessor {
    * exceptions, but instead just log an error string when something goes wrong.
    */
   template <typename... Args>
-  std::string formatLogString(folly::StringPiece fmt, Args&&... args) noexcept {
+  std::string formatLogString(
+      folly::StringPiece fmt,
+      const Args&... args) noexcept {
     try {
-      return folly::sformat(fmt, std::forward<Args>(args)...);
+      return folly::sformat(fmt, args...);
     } catch (const std::exception& ex) {
       // This most likely means that the caller had a bug in their format
       // string/arguments.  Handle the exception here, rather than letting it
       // propagate up, since callers generally do not expect log statements to
       // throw.
       //
-      // Log the format string by itself, to help the developer at least
-      // identify the buggy format string in their code.
-      return folly::to<std::string>(
-          "error formatting log message: ",
-          ex.what(),
-          "; format string: \"",
-          fmt,
-          "\"");
+      // Log the format string and as much of the arguments as we can convert,
+      // to aid debugging.
+      std::string result;
+      result.append("error formatting log message: ");
+      result.append(ex.what());
+      result.append("; format string: \"");
+      result.append(fmt.data(), fmt.size());
+      result.append("\", arguments: ");
+      fallbackFormat(&result, args...);
+      return result;
     }
   }
 
+  /**
+   * Helper function generate a fallback version of the arguments in case
+   * folly::sformat() throws an exception.
+   *
+   * This attempts to convert each argument to a string using a similar
+   * mechanism to folly::to<std::string>(), if supported.
+   */
+  template <typename Arg1, typename... Args>
+  void
+  fallbackFormat(std::string* str, const Arg1& arg1, const Args&... remainder) {
+    detail::fallbackFormatOneArg(str, &arg1, 0);
+    str->append(", ");
+    fallbackFormat(str, remainder...);
+  }
+
+  template <typename Arg>
+  void fallbackFormat(std::string* str, const Arg& arg) {
+    detail::fallbackFormatOneArg(str, &arg, 0);
+  }
+
   const LogCategory* const category_;
   LogLevel const level_;
   folly::StringPiece filename_;

diff --git a/folly/experimental/logging/test/LoggerTest.cpp b/folly/experimental/logging/test/LoggerTest.cpp
index 64c52c2edb6e51e048e7a13676edb2788b0279f5..0afedd9bc3477fed0c68d0667f663606368dd325 100644 (file)
--- a/folly/experimental/logging/test/LoggerTest.cpp
+++ b/folly/experimental/logging/test/LoggerTest.cpp
@@ -107,7 +107,8 @@ TEST_F(LoggerTest, follyFormatError) {
   EXPECT_EQ(
       "error formatting log message: "
       "invalid format argument {:6.3f}: invalid specifier 'f'; "
-      "format string: \"param1: {:06d}, param2: {:6.3f}\"",
+      "format string: \"param1: {:06d}, param2: {:6.3f}\", "
+      "arguments: (int: 1234), (char [13]: hello world!)",
       messages[0].first.getMessage());
   EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
   EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel());
@@ -133,6 +134,7 @@ TEST_F(LoggerTest, toString) {
 }
 
 class ToStringFailure {};
+class FormattableButNoToString {};
 
 [[noreturn]] void toAppend(
     const ToStringFailure& /* arg */,
@@ -141,6 +143,30 @@ class ToStringFailure {};
       "error converting ToStringFailure object to a string");
 }
 
+namespace folly {
+template <>
+class FormatValue<ToStringFailure> {
+ public:
+  explicit FormatValue(ToStringFailure) {}
+
+  template <class FormatCallback>
+  void format(FormatArg& arg, FormatCallback& cb) const {
+    FormatValue<std::string>("ToStringFailure").format(arg, cb);
+  }
+};
+
+template <>
+class FormatValue<FormattableButNoToString> {
+ public:
+  explicit FormatValue(FormattableButNoToString) {}
+
+  template <class FormatCallback>
+  void format(FormatArg&, FormatCallback&) const {
+    throw std::runtime_error("test");
+  }
+};
+}
+
 TEST_F(LoggerTest, toStringError) {
   // Use the folly::to<string> log API, with an object that will throw
   // an exception when we try to convert it to a string.
@@ -165,6 +191,47 @@ TEST_F(LoggerTest, toStringError) {
   EXPECT_EQ(logger_.getCategory(), messages[0].second);
 }
 
+TEST_F(LoggerTest, formatFallbackError) {
+  // Check the behavior if logf() fails, and toAppend() also fails.
+  ToStringFailure obj;
+  FB_LOGF(logger_, WARN, "param1: {}, param2: {}, {}", 1234, obj);
+
+  auto& messages = handler_->getMessages();
+  ASSERT_EQ(1, messages.size());
+  EXPECT_EQ(
+      "error formatting log message: "
+      "invalid format argument {}: argument index out of range, max=2; "
+      "format string: \"param1: {}, param2: {}, {}\", "
+      "arguments: (int: 1234), (ToStringFailure: <error_converting_to_string>)",
+      messages[0].first.getMessage());
+  EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
+  EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel());
+  EXPECT_FALSE(messages[0].first.containsNewlines());
+  EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
+  EXPECT_EQ(logger_.getCategory(), messages[0].second);
+}
+
+TEST_F(LoggerTest, formatFallbackUnsupported) {
+  // Check the behavior if logf() fails, and toAppend() also fails.
+  FormattableButNoToString obj;
+  FB_LOGF(logger_, WARN, "param1: {}, param2: {}", 1234, obj);
+
+  auto& messages = handler_->getMessages();
+  ASSERT_EQ(1, messages.size());
+  EXPECT_EQ(
+      "error formatting log message: "
+      "test; "
+      "format string: \"param1: {}, param2: {}\", "
+      "arguments: (int: 1234), "
+      "(FormattableButNoToString: <no_string_conversion>)",
+      messages[0].first.getMessage());
+  EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName()));
+  EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel());
+  EXPECT_FALSE(messages[0].first.containsNewlines());
+  EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory());
+  EXPECT_EQ(logger_.getCategory(), messages[0].second);
+}
+
 TEST_F(LoggerTest, streamingArgs) {
   auto& messages = handler_->getMessages();
 
@@ -270,7 +337,8 @@ TEST_F(LoggerTest, logMacros) {
   EXPECT_EQ(
       "error formatting log message: "
       "invalid format argument {}: argument index out of range, max=1; "
-      "format string: \"whoops: {}, {}\"",
+      "format string: \"whoops: {}, {}\", "
+      "arguments: (int: 5)",
       messages[0].first.getMessage());
   messages.clear();
 }