From: Adam Simpkins Date: Tue, 13 Jun 2017 01:33:05 +0000 (-0700) Subject: logging: add support for streaming operators X-Git-Tag: v2017.06.19.00~31 X-Git-Url: http://plrg.eecs.uci.edu/git/?p=folly.git;a=commitdiff_plain;h=dc2c2837d095c9d3a5407e939a88b982ba37858a logging: add support for streaming operators Summary: Update the logging library so that FB_LOG() and FB_LOGF() also accept streaming style arguments: FB_LOG(logger) << "logs can be written like this now: " << 1234; FB_LOG(logger, "both styles can be used") << " together"; FB_LOGF(logger, "test: {}, {}", 1234, 5678) << " and with FB_LOGF() too"; Streaming support does make the upcoming XLOG() macros more complicated to implement, since the macro has to expand to a single ternary `?` expression. However I was able to come up with a solution that works and has minimal overhead. Reviewed By: wez Differential Revision: D5082979 fbshipit-source-id: 11734e39c02ad28aceb44bbfbd137d781caa30cf --- diff --git a/CMakeLists.txt b/CMakeLists.txt index 9bb0f26f..deb87fd4 100755 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -324,6 +324,7 @@ if (BUILD_TESTS) LogLevelTest.cpp LogMessageTest.cpp LogNameTest.cpp + LogStreamTest.cpp DIRECTORY fibers/test/ TEST fibers_test SOURCES FibersTest.cpp diff --git a/folly/Makefile.am b/folly/Makefile.am index ca6b9409..9b177ccb 100644 --- a/folly/Makefile.am +++ b/folly/Makefile.am @@ -126,6 +126,8 @@ nobase_follyinclude_HEADERS = \ experimental/logging/LogLevel.h \ experimental/logging/LogMessage.h \ experimental/logging/LogName.h \ + experimental/logging/LogStream.h \ + experimental/logging/LogStreamProcessor.h \ experimental/logging/Logger.h \ experimental/logging/LoggerDB.h \ experimental/NestedCommandLineApp.h \ diff --git a/folly/experimental/logging/LogCategory.cpp b/folly/experimental/logging/LogCategory.cpp index f6fcc109..f1b2856c 100644 --- a/folly/experimental/logging/LogCategory.cpp +++ b/folly/experimental/logging/LogCategory.cpp @@ -42,7 +42,7 @@ LogCategory::LogCategory(StringPiece name, LogCategory* parent) parent_->firstChild_ = this; } -void LogCategory::processMessage(const LogMessage& message) { +void LogCategory::processMessage(const LogMessage& message) const { // Make a copy of any attached LogHandlers, so we can release the handlers_ // lock before holding them. // diff --git a/folly/experimental/logging/LogCategory.h b/folly/experimental/logging/LogCategory.h index ea6aca22..a9447133 100644 --- a/folly/experimental/logging/LogCategory.h +++ b/folly/experimental/logging/LogCategory.h @@ -98,6 +98,23 @@ class LogCategory { return effectiveLevel_.load(std::memory_order_relaxed); } + /** + * Check whether this Logger or any of its parent Loggers would do anything + * with a log message at the given level. + */ + bool logCheck(LogLevel level) const { + // We load the effective level using std::memory_order_relaxed. + // + // We want to make log checks as lightweight as possible. It's fine if we + // don't immediately respond to changes made to the log level from other + // threads. We can wait until some other operation triggers a memory + // barrier before we honor the new log level setting. No other memory + // accesses depend on the log level value. Callers should not rely on all + // other threads to immediately stop logging as soon as they decrease the + // log level for a given category. + return effectiveLevel_.load(std::memory_order_relaxed) <= level; + } + /** * Set the log level for this LogCategory. * @@ -123,7 +140,7 @@ class LogCategory { * LogHandlers attached to this LogCategory, without any additional log level * checks (apart from the ones done in the LogHandlers). */ - void processMessage(const LogMessage& message); + void processMessage(const LogMessage& message) const; /** * Get the LoggerDB that this LogCategory belongs to. diff --git a/folly/experimental/logging/LogStream.cpp b/folly/experimental/logging/LogStream.cpp new file mode 100644 index 00000000..947d76d7 --- /dev/null +++ b/folly/experimental/logging/LogStream.cpp @@ -0,0 +1,54 @@ +/* + * Copyright 2004-present Facebook, Inc. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +#include + +namespace folly { + +LogStreamBuffer::int_type LogStreamBuffer::overflow(int_type ch) { + auto currentSize = str_.size(); + size_t newSize; + if (currentSize == 0) { + newSize = kInitialCapacity; + } else { + // Increase by 1.25 each time + newSize = currentSize + (currentSize >> 2); + } + + try { + str_.resize(newSize); + + if (ch == EOF) { + setp((&str_.front()) + currentSize, (&str_.front()) + newSize); + return 'x'; + } else { + str_[currentSize] = static_cast(ch); + setp((&str_.front()) + currentSize + 1, (&str_.front()) + newSize); + return ch; + } + } catch (const std::exception& ex) { + // Return EOF to indicate that the operation failed. + // In general the only exception we really expect to see here is + // std::bad_alloc() from the str_.resize() call. + return EOF; + } +} + +LogStream::LogStream() { + rdbuf(&buffer_); +} + +LogStream::~LogStream() {} +} diff --git a/folly/experimental/logging/LogStream.h b/folly/experimental/logging/LogStream.h new file mode 100644 index 00000000..82987f1f --- /dev/null +++ b/folly/experimental/logging/LogStream.h @@ -0,0 +1,79 @@ +/* + * Copyright 2004-present Facebook, Inc. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +#pragma once + +#include + +#include +#include + +namespace folly { + +/** + * A std::streambuf implementation for use by LogStream + */ +class LogStreamBuffer : public std::streambuf { + public: + LogStreamBuffer() { + // We intentionally do not reserve any string buffer space initially, + // since this will not be needed for XLOG() and XLOGF() statements + // that do not use the streaming API. (e.g., XLOG(INFO, "test ", 1234) ) + } + + bool empty() const { + return str_.empty(); + } + + std::string extractString() { + str_.resize(pptr() - (&str_.front())); + return std::move(str_); + } + + int_type overflow(int_type ch) override; + + private: + enum : size_t { kInitialCapacity = 256 }; + std::string str_; +}; + +/** + * A std::ostream implementation for use by the logging macros. + * + * All-in-all this is pretty similar to std::stringstream, but lets us + * destructively extract an rvalue-reference to the underlying string. + */ +class LogStream : public std::ostream { + public: + // Explicitly declare the default constructor and destructor, but only + // define them in the .cpp file. This prevents them from being inlined at + // each FB_LOG() or XLOG() statement. Inlining them just causes extra code + // bloat, with minimal benefit--for debug log statements these never even get + // called in the common case where the log statement is disabled. + LogStream(); + ~LogStream(); + + bool empty() const { + return buffer_.empty(); + } + + std::string extractString() { + return buffer_.extractString(); + } + + private: + LogStreamBuffer buffer_; +}; +} diff --git a/folly/experimental/logging/LogStreamProcessor.cpp b/folly/experimental/logging/LogStreamProcessor.cpp new file mode 100644 index 00000000..e70df787 --- /dev/null +++ b/folly/experimental/logging/LogStreamProcessor.cpp @@ -0,0 +1,63 @@ +/* + * Copyright 2004-present Facebook, Inc. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +#include + +#include + +#include + +namespace folly { +void LogStreamProcessor::operator&(std::ostream& stream) noexcept { + // Note that processMessage() is not noexcept and theoretically may throw. + // However, the only exception that should be possible is std::bad_alloc if + // we fail to allocate memory. We intentionally let our noexcept specifier + // crash in that case, since the program likely won't be able to continue + // anyway. + // + // Any other error here is unexpected and we also want to fail hard + // in that situation too. + auto& logStream = static_cast(stream); + category_->processMessage(LogMessage{category_, + level_, + filename_, + lineNumber_, + extractMessageString(logStream)}); +} + +void LogStreamProcessor::operator&(LogStream&& stream) noexcept { + // This version of operator&() is generally only invoked when + // no streaming arguments were supplied to the logging macro. + // Therefore we don't bother calling extractMessageString(stream), + // and just directly use message_. + assert(stream.empty()); + + category_->processMessage(LogMessage{ + category_, level_, filename_, lineNumber_, std::move(message_)}); +} + +std::string LogStreamProcessor::extractMessageString( + LogStream& stream) noexcept { + if (stream.empty()) { + return std::move(message_); + } + + if (message_.empty()) { + return stream.extractString(); + } + message_.append(stream.extractString()); + return std::move(message_); +} +} diff --git a/folly/experimental/logging/LogStreamProcessor.h b/folly/experimental/logging/LogStreamProcessor.h new file mode 100644 index 00000000..b68de952 --- /dev/null +++ b/folly/experimental/logging/LogStreamProcessor.h @@ -0,0 +1,188 @@ +/* + * Copyright 2004-present Facebook, Inc. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +#pragma once + +#include +#include +#include +#include + +namespace folly { + +class LogStream; + +/** + * LogStreamProcessor receives a LogStream and logs it. + * + * This class is primarily intended to be used through the FB_LOG*() macros. + * Its API is designed to support these macros, and is not designed for other + * use. + * + * The operator&() method is used to trigger the logging. + * This operator is used because it has lower precedence than <<, but higher + * precedence than the ? ternary operator, allowing it to bind with the correct + * precedence in the log macro implementations. + */ +class LogStreamProcessor { + public: + enum AppendType { APPEND }; + enum FormatType { FORMAT }; + + /** + * LogStreamProcessor constructor for use with a LOG() macro with no extra + * arguments. + * + * Note that the filename argument is not copied. The caller should ensure + * that it points to storage that will remain valid for the lifetime of the + * LogStreamProcessor. (This is always the case for the __FILE__ + * preprocessor macro.) + */ + LogStreamProcessor( + const LogCategory* category, + LogLevel level, + folly::StringPiece filename, + unsigned int lineNumber, + AppendType) noexcept + : category_{category}, + level_{level}, + filename_{filename}, + lineNumber_{lineNumber} {} + + /** + * LogStreamProcessor constructor for use with a LOG() macro with arguments + * to be concatenated with folly::to() + * + * Note that the filename argument is not copied. The caller should ensure + * that it points to storage that will remain valid for the lifetime of the + * LogStreamProcessor. (This is always the case for the __FILE__ + * preprocessor macro.) + */ + template + LogStreamProcessor( + const LogCategory* category, + LogLevel level, + const char* filename, + unsigned int lineNumber, + AppendType, + Args&&... args) noexcept + : category_{category}, + level_{level}, + filename_{filename}, + lineNumber_{lineNumber}, + message_{createLogString(std::forward(args)...)} {} + + /** + * LogStreamProcessor constructor for use with a LOG() macro with arguments + * to be concatenated with folly::to() + * + * Note that the filename argument is not copied. The caller should ensure + * that it points to storage that will remain valid for the lifetime of the + * LogStreamProcessor. (This is always the case for the __FILE__ + * preprocessor macro.) + */ + template + LogStreamProcessor( + const LogCategory* category, + LogLevel level, + const char* filename, + unsigned int lineNumber, + FormatType, + folly::StringPiece fmt, + Args&&... args) noexcept + : category_{category}, + level_{level}, + filename_{filename}, + lineNumber_{lineNumber}, + message_{formatLogString(fmt, std::forward(args)...)} {} + + /** + * This version of operator&() is typically used when the user specifies + * log arguments using the << stream operator. The operator<<() generally + * returns a std::ostream& + */ + void operator&(std::ostream& stream) noexcept; + + /** + * This version of operator&() is used when no extra arguments are specified + * with the << operator. In this case the & operator is applied directly to + * the temporary LogStream object. + */ + void operator&(LogStream&& stream) noexcept; + + private: + std::string extractMessageString(LogStream& stream) noexcept; + + /** + * Construct a log message string using folly::to() + * + * This function attempts to avoid throwing exceptions. If an error occurs + * during formatting, a message including the error details is returned + * instead. This is done to help ensure that log statements do not generate + * exceptions, but instead just log an error string when something goes wrong. + */ + template + std::string createLogString(Args&&... args) noexcept { + try { + return folly::to(std::forward(args)...); + } catch (const std::exception& ex) { + // This most likely means there was some error converting the arguments + // to strings. Handle the exception here, rather than letting it + // propagate up, since callers generally do not expect log statements to + // throw. + // + // Just log an error message letting indicating that something went wrong + // formatting the log message. + return folly::to( + "error constructing log message: ", ex.what()); + } + } + + /** + * Construct a log message string using folly::sformat() + * + * This function attempts to avoid throwing exceptions. If an error occurs + * during formatting, a message including the error details is returned + * instead. This is done to help ensure that log statements do not generate + * exceptions, but instead just log an error string when something goes wrong. + */ + template + std::string formatLogString(folly::StringPiece fmt, Args&&... args) noexcept { + try { + return folly::sformat(fmt, std::forward(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, + "\""); + } + } + + const LogCategory* const category_; + LogLevel const level_; + folly::StringPiece filename_; + unsigned int lineNumber_; + std::string message_; +}; +} diff --git a/folly/experimental/logging/Logger.cpp b/folly/experimental/logging/Logger.cpp index 63ad5ae0..eb8a9616 100644 --- a/folly/experimental/logging/Logger.cpp +++ b/folly/experimental/logging/Logger.cpp @@ -31,22 +31,4 @@ Logger::Logger(LogCategory* cat) : category_(cat) {} Logger::Logger(LoggerDB* db, StringPiece name) : Logger{db->getCategory(name)} {} - -void Logger::log( - LogLevel level, - StringPiece filename, - unsigned int lineNumber, - std::string&& msg) const { - category_->processMessage( - LogMessage{category_, level, filename, lineNumber, std::move(msg)}); -} - -void Logger::log( - LogLevel level, - StringPiece filename, - unsigned int lineNumber, - folly::StringPiece msg) const { - category_->processMessage( - LogMessage{category_, level, filename, lineNumber, msg}); -} } diff --git a/folly/experimental/logging/Logger.h b/folly/experimental/logging/Logger.h index 4f743d1d..ab9bd24f 100644 --- a/folly/experimental/logging/Logger.h +++ b/folly/experimental/logging/Logger.h @@ -19,22 +19,40 @@ #include #include #include +#include +#include + +/** + * Helper macro for implementing FB_LOG() and FB_LOGF(). + * + * This macro generally should not be used directly by end users. + */ +#define FB_LOG_IMPL(logger, level, type, ...) \ + (!(logger).getCategory()->logCheck(level)) \ + ? (void)0 \ + : ::folly::LogStreamProcessor{(logger).getCategory(), \ + (level), \ + __FILE__, \ + __LINE__, \ + (type), \ + ##__VA_ARGS__} & \ + ::folly::LogStream() /** * Log a message to the specified logger. * * This macro avoids evaluating the log arguments unless the log level check * succeeds. + * + * Beware that the logger argument is evaluated twice, so this argument should + * be an expression with no side-effects. */ -#define FB_LOG(logger, level, msg, ...) \ - do { \ - const auto fbLogLevelTmp = ::folly::LogLevel::level; \ - const auto& fbLoggerTmp = (logger); \ - if (fbLoggerTmp.logCheck(fbLogLevelTmp)) { \ - fbLoggerTmp.log( \ - fbLogLevelTmp, __FILE__, __LINE__, (msg), ##__VA_ARGS__); \ - } \ - } while (0) +#define FB_LOG(logger, level, ...) \ + FB_LOG_IMPL( \ + logger, \ + ::folly::LogLevel::level, \ + ::folly::LogStreamProcessor::APPEND, \ + ##__VA_ARGS__) /** * Log a message to the specified logger, using a folly::format() string. @@ -44,16 +62,18 @@ * * This macro avoids evaluating the log arguments unless the log level check * succeeds. + * + * Beware that the logger argument is evaluated twice, so this argument should + * be an expression with no side-effects. */ -#define FB_LOGF(logger, level, fmt, ...) \ - do { \ - const auto fbLogLevelTmp = ::folly::LogLevel::level; \ - const auto& fbLoggerTmp = (logger); \ - if (fbLoggerTmp.logCheck(fbLogLevelTmp)) { \ - fbLoggerTmp.logf( \ - fbLogLevelTmp, __FILE__, __LINE__, (fmt), ##__VA_ARGS__); \ - } \ - } while (0) +#define FB_LOGF(logger, level, fmt, arg1, ...) \ + FB_LOG_IMPL( \ + logger, \ + ::folly::LogLevel::level, \ + ::folly::LogStreamProcessor::FORMAT, \ + fmt, \ + arg1, \ + ##__VA_ARGS__) namespace folly { @@ -91,114 +111,6 @@ class Logger { */ Logger(LoggerDB* db, folly::StringPiece name); - /** - * Get the effective level for this logger. - * - * This is the minimum log level of this logger, or any of its parents. - * Log messages below this level will be ignored, while messages at or - * above this level need to be processed by this logger or one of its - * parents. - */ - LogLevel getEffectiveLevel() const { - return category_->getEffectiveLevel(); - } - - /** - * Check whether this Logger or any of its parent Loggers would do anything - * with a log message at the given level. - */ - bool logCheck(LogLevel level) const { - // We load the effective level using std::memory_order_relaxed. - // - // We want to make log checks as lightweight as possible. It's fine if we - // don't immediately respond to changes made to the log level from other - // threads. We can wait until some other operation triggers a memory - // barrier before we honor the new log level setting. No other memory - // accesses depend on the log level value. Callers should not rely on all - // other threads to immediately stop logging as soon as they decrease the - // log level for a given category. - return category_->getEffectiveLevelRelaxed() <= level; - } - - /** - * Unconditionally log a message. - * - * The caller is responsible for calling logCheck() before log() to ensure - * that this log message should be admitted. This is typically done with one - * of the logging macros. - */ - void log( - LogLevel level, - folly::StringPiece filename, - unsigned int lineNumber, - std::string&& msg) const; - void log( - LogLevel level, - folly::StringPiece filename, - unsigned int lineNumber, - folly::StringPiece msg) const; - - /** - * Unconditionally log a message. - * - * This concatenates the arguments into a string using - * folly::to() - */ - template - void log( - LogLevel level, - folly::StringPiece filename, - unsigned int lineNumber, - Args&&... args) const { - std::string msg; - try { - msg = folly::to(std::forward(args)...); - } catch (const std::exception& ex) { - // This most likely means there was some error converting the arguments - // to strings. Handle the exception here, rather than letting it - // propagate up, since callers generally do not expect log statements to - // throw. - // - // Just log an error message letting indicating that something went wrong - // formatting the log message. - msg = - folly::to("error constructing log message: ", ex.what()); - } - log(level, filename, lineNumber, std::move(msg)); - } - - /** - * Unconditionally log a message using a format string. - * - * This uses folly::format() to format the message. - */ - template - void logf( - LogLevel level, - folly::StringPiece filename, - unsigned int lineNumber, - folly::StringPiece fmt, - Args&&... args) const { - std::string msg; - try { - msg = folly::sformat(fmt, std::forward(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. - msg = folly::to( - "error formatting log message: ", - ex.what(), - "; format string: ", - fmt); - } - log(level, filename, lineNumber, std::move(msg)); - } - /** * Get the LogCategory that this Logger refers to. */ diff --git a/folly/experimental/logging/Makefile.am b/folly/experimental/logging/Makefile.am index 3501af15..683017cf 100644 --- a/folly/experimental/logging/Makefile.am +++ b/folly/experimental/logging/Makefile.am @@ -9,7 +9,9 @@ libfollylogging_la_SOURCES = \ LogHandler.cpp \ LogLevel.cpp \ LogMessage.cpp \ - LogName.cpp + LogName.cpp \ + LogStream.cpp \ + LogStreamProcessor.cpp libfollylogging_la_LIBADD = $(top_builddir)/libfolly.la libfollylogging_la_LDFLAGS = $(AM_LDFLAGS) -version-info $(LT_VERSION) diff --git a/folly/experimental/logging/test/LogStreamTest.cpp b/folly/experimental/logging/test/LogStreamTest.cpp new file mode 100644 index 00000000..29fea09e --- /dev/null +++ b/folly/experimental/logging/test/LogStreamTest.cpp @@ -0,0 +1,38 @@ +/* + * Copyright 2004-present Facebook, Inc. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +#include +#include + +using namespace folly; + +TEST(LogStream, simple) { + LogStream ls; + ls << "test"; + ls << " foobar"; + + EXPECT_EQ("test foobar", ls.extractString()); +} + +TEST(LogStream, largeMessage) { + std::string largeString(4096, 'a'); + + LogStream ls; + ls << "prefix "; + ls << largeString; + ls << " suffix"; + + EXPECT_EQ("prefix " + largeString + " suffix", ls.extractString()); +} diff --git a/folly/experimental/logging/test/LoggerTest.cpp b/folly/experimental/logging/test/LoggerTest.cpp index e9b5d4b9..64c52c2e 100644 --- a/folly/experimental/logging/test/LoggerTest.cpp +++ b/folly/experimental/logging/test/LoggerTest.cpp @@ -34,6 +34,14 @@ class LoggerTest : public ::testing::Test { category->setLevel(LogLevel::DEBUG, true); } + static StringPiece pathBasename(StringPiece path) { + auto idx = path.rfind('/'); + if (idx == StringPiece::npos) { + return path.str(); + } + return path.subpiece(idx + 1); + } + LoggerDB db_{LoggerDB::TESTING}; Logger logger_{&db_, "test"}; std::shared_ptr handler_; @@ -41,13 +49,14 @@ class LoggerTest : public ::testing::Test { TEST_F(LoggerTest, basic) { // Simple log message - logger_.log(LogLevel::WARN, "src/myproject/myfile.cpp", 1234, "hello world"); + auto expectedLine = __LINE__ + 1; + FB_LOG(logger_, WARN, "hello world"); auto& messages = handler_->getMessages(); ASSERT_EQ(1, messages.size()); EXPECT_EQ("hello world", messages[0].first.getMessage()); - EXPECT_EQ("src/myproject/myfile.cpp", messages[0].first.getFileName()); - EXPECT_EQ(1234, messages[0].first.getLineNumber()); + EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName())); + EXPECT_EQ(expectedLine, messages[0].first.getLineNumber()); EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel()); EXPECT_FALSE(messages[0].first.containsNewlines()); EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory()); @@ -57,13 +66,14 @@ TEST_F(LoggerTest, basic) { TEST_F(LoggerTest, subCategory) { // Log from a sub-category. Logger subLogger{&db_, "test.foo.bar"}; - subLogger.log(LogLevel::ERROR, "myfile.cpp", 99, "sub-category\nlog message"); + auto expectedLine = __LINE__ + 1; + FB_LOG(subLogger, ERROR, "sub-category\nlog message"); auto& messages = handler_->getMessages(); ASSERT_EQ(1, messages.size()); EXPECT_EQ("sub-category\nlog message", messages[0].first.getMessage()); - EXPECT_EQ("myfile.cpp", messages[0].first.getFileName()); - EXPECT_EQ(99, messages[0].first.getLineNumber()); + EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName())); + EXPECT_EQ(expectedLine, messages[0].first.getLineNumber()); EXPECT_EQ(LogLevel::ERROR, messages[0].first.getLevel()); EXPECT_TRUE(messages[0].first.containsNewlines()); EXPECT_EQ(subLogger.getCategory(), messages[0].first.getCategory()); @@ -71,20 +81,15 @@ TEST_F(LoggerTest, subCategory) { } TEST_F(LoggerTest, formatMessage) { - logger_.logf( - LogLevel::WARN, - "log.cpp", - 9, - "num events: {:06d}, duration: {:6.3f}", - 1234, - 5.6789); + auto expectedLine = __LINE__ + 1; + FB_LOGF(logger_, WARN, "num events: {:06d}, duration: {:6.3f}", 1234, 5.6789); auto& messages = handler_->getMessages(); ASSERT_EQ(1, messages.size()); EXPECT_EQ( "num events: 001234, duration: 5.679", messages[0].first.getMessage()); - EXPECT_EQ("log.cpp", messages[0].first.getFileName()); - EXPECT_EQ(9, messages[0].first.getLineNumber()); + EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName())); + EXPECT_EQ(expectedLine, messages[0].first.getLineNumber()); EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel()); EXPECT_FALSE(messages[0].first.containsNewlines()); EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory()); @@ -94,23 +99,17 @@ TEST_F(LoggerTest, formatMessage) { TEST_F(LoggerTest, follyFormatError) { // If we pass in a bogus format string, logf() should not throw. // It should instead log a message, just complaining about the format error. - logger_.logf( - LogLevel::WARN, - "log.cpp", - 9, - "param1: {:06d}, param2: {:6.3f}", - 1234, - "hello world!"); + FB_LOGF( + logger_, WARN, "param1: {:06d}, param2: {:6.3f}", 1234, "hello world!"); auto& messages = handler_->getMessages(); ASSERT_EQ(1, messages.size()); 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}\"", messages[0].first.getMessage()); - EXPECT_EQ("log.cpp", messages[0].first.getFileName()); - EXPECT_EQ(9, messages[0].first.getLineNumber()); + 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()); @@ -119,13 +118,14 @@ TEST_F(LoggerTest, follyFormatError) { TEST_F(LoggerTest, toString) { // Use the log API that calls folly::to - logger_.log(LogLevel::DBG5, "log.cpp", 3, "status=", 5, " name=", "foobar"); + auto expectedLine = __LINE__ + 1; + FB_LOG(logger_, DBG5, "status=", 5, " name=", "foobar"); auto& messages = handler_->getMessages(); ASSERT_EQ(1, messages.size()); EXPECT_EQ("status=5 name=foobar", messages[0].first.getMessage()); - EXPECT_EQ("log.cpp", messages[0].first.getFileName()); - EXPECT_EQ(3, messages[0].first.getLineNumber()); + EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName())); + EXPECT_EQ(expectedLine, messages[0].first.getLineNumber()); EXPECT_EQ(LogLevel::DBG5, messages[0].first.getLevel()); EXPECT_FALSE(messages[0].first.containsNewlines()); EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory()); @@ -148,7 +148,8 @@ TEST_F(LoggerTest, toStringError) { // The logging code should not throw, but should instead log a message // with some detail about the failure. ToStringFailure obj; - logger_.log(LogLevel::DBG1, "log.cpp", 3, "status=", obj, " name=", "foobar"); + auto expectedLine = __LINE__ + 1; + FB_LOG(logger_, DBG1, "status=", obj, " name=", "foobar"); auto& messages = handler_->getMessages(); ASSERT_EQ(1, messages.size()); @@ -156,24 +157,64 @@ TEST_F(LoggerTest, toStringError) { "error constructing log message: " "error converting ToStringFailure object to a string", messages[0].first.getMessage()); - EXPECT_EQ("log.cpp", messages[0].first.getFileName()); - EXPECT_EQ(3, messages[0].first.getLineNumber()); + EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName())); + EXPECT_EQ(expectedLine, messages[0].first.getLineNumber()); EXPECT_EQ(LogLevel::DBG1, 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(); + + // Test with only streaming arguments + std::string foo = "bar"; + FB_LOG(logger_, WARN) << "foo=" << foo << ", test=0x" << std::hex << 35; + ASSERT_EQ(1, messages.size()); + EXPECT_EQ("foo=bar, test=0x23", 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); + messages.clear(); + + // Test with both function-style and streaming arguments + FB_LOG(logger_, WARN, "foo=", foo) << " hello, " + << "world: " << 34; + ASSERT_EQ(1, messages.size()); + EXPECT_EQ("foo=bar hello, world: 34", 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); + messages.clear(); + + // Test with format-style and streaming arguments + FB_LOGF(logger_, WARN, "foo={}, x={}", foo, 34) << ", also " << 12; + ASSERT_EQ(1, messages.size()); + EXPECT_EQ("foo=bar, x=34, also 12", 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); + messages.clear(); +} + TEST_F(LoggerTest, escapeSequences) { // Escape characters (and any other unprintable characters) in the log // message should be escaped when logged. - logger_.log(LogLevel::WARN, "termcap.cpp", 34, "hello \033[34mworld\033[0m!"); + auto expectedLine = __LINE__ + 1; + FB_LOG(logger_, WARN, "hello \033[34mworld\033[0m!"); auto& messages = handler_->getMessages(); ASSERT_EQ(1, messages.size()); EXPECT_EQ("hello \\x1b[34mworld\\x1b[0m!", messages[0].first.getMessage()); - EXPECT_EQ("termcap.cpp", messages[0].first.getFileName()); - EXPECT_EQ(34, messages[0].first.getLineNumber()); + EXPECT_EQ("LoggerTest.cpp", pathBasename(messages[0].first.getFileName())); + EXPECT_EQ(expectedLine, messages[0].first.getLineNumber()); EXPECT_EQ(LogLevel::WARN, messages[0].first.getLevel()); EXPECT_FALSE(messages[0].first.containsNewlines()); EXPECT_EQ(logger_.getCategory(), messages[0].first.getCategory()); @@ -229,7 +270,7 @@ 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: {}, {}\"", messages[0].first.getMessage()); messages.clear(); }