From: Adam Simpkins Date: Tue, 13 Jun 2017 01:33:06 +0000 (-0700) Subject: logging: if folly::format() fails, also log the arguments X-Git-Tag: v2017.06.19.00~30 X-Git-Url: http://plrg.eecs.uci.edu/git/?p=folly.git;a=commitdiff_plain;h=ba74a196a02f5b75d90225bb3ab7cb441ae58de5 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() 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 b68de952..f95e00e4 100644 --- a/folly/experimental/logging/LogStreamProcessor.h +++ b/folly/experimental/logging/LogStreamProcessor.h @@ -16,6 +16,7 @@ #pragma once #include +#include #include #include #include @@ -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 +auto fallbackFormatOneArg(std::string* str, const Arg* arg, int) -> decltype( + toAppend(std::declval(), std::declval()), + std::declval()) { + 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(""); + } + str->push_back(')'); +} + +template +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(")"); +} +} + /** * 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 - 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)...); + 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( - "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(), if supported. + */ + template + void + fallbackFormat(std::string* str, const Arg1& arg1, const Args&... remainder) { + detail::fallbackFormatOneArg(str, &arg1, 0); + str->append(", "); + fallbackFormat(str, remainder...); + } + + template + 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 64c52c2e..0afedd9b 100644 --- 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 { + public: + explicit FormatValue(ToStringFailure) {} + + template + void format(FormatArg& arg, FormatCallback& cb) const { + FormatValue("ToStringFailure").format(arg, cb); + } +}; + +template <> +class FormatValue { + public: + explicit FormatValue(FormattableButNoToString) {} + + template + void format(FormatArg&, FormatCallback&) const { + throw std::runtime_error("test"); + } +}; +} + TEST_F(LoggerTest, toStringError) { // Use the folly::to 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: )", + 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: )", + 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(); }