From: Adam Simpkins Date: Thu, 15 Jun 2017 18:03:58 +0000 (-0700) Subject: logging: add GlogStyleFormatter X-Git-Tag: v2017.06.19.00~15 X-Git-Url: http://plrg.eecs.uci.edu/git/?p=folly.git;a=commitdiff_plain;h=48b88f01eea69670925b0fac831fee553c5c2c18 logging: add GlogStyleFormatter Summary: Add a LogFormatter implementation that logs messages using a similar format to the glog library. Reviewed By: wez Differential Revision: D5083108 fbshipit-source-id: 75f0a6b78ce5406b4557d6c4394f033d5e019f71 --- diff --git a/CMakeLists.txt b/CMakeLists.txt index 1db5d952..820cec10 100755 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -321,6 +321,7 @@ if (BUILD_TESTS) XlogHeader2.h SOURCES AsyncFileWriterTest.cpp + GlogFormatterTest.cpp ImmediateFileWriterTest.cpp LogCategoryTest.cpp LoggerDBTest.cpp diff --git a/folly/Makefile.am b/folly/Makefile.am index aa1a473c..734be3dd 100644 --- a/folly/Makefile.am +++ b/folly/Makefile.am @@ -122,6 +122,7 @@ nobase_follyinclude_HEADERS = \ experimental/JSONSchema.h \ experimental/LockFreeRingBuffer.h \ experimental/logging/AsyncFileWriter.h \ + experimental/logging/GlogStyleFormatter.h \ experimental/logging/ImmediateFileWriter.h \ experimental/logging/LogCategory.h \ experimental/logging/LogFormatter.h \ diff --git a/folly/experimental/logging/GlogStyleFormatter.cpp b/folly/experimental/logging/GlogStyleFormatter.cpp new file mode 100644 index 00000000..cf8c7a7b --- /dev/null +++ b/folly/experimental/logging/GlogStyleFormatter.cpp @@ -0,0 +1,128 @@ +/* + * 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 +#include + +namespace { +using folly::StringPiece; +using folly::LogLevel; + +StringPiece getGlogLevelName(LogLevel level) { + if (level < LogLevel::INFO) { + return "VERBOSE"; + } else if (level < LogLevel::WARN) { + return "INFO"; + } else if (level < LogLevel::ERROR) { + return "WARNING"; + } else if (level < LogLevel::CRITICAL) { + return "ERROR"; + } + return "CRITICAL"; +} +} + +namespace folly { + +std::string GlogStyleFormatter::formatMessage( + const LogMessage& message, + const LogCategory* /* handlerCategory */) { + // Get the local time info + struct tm ltime; + auto timeSinceEpoch = message.getTimestamp().time_since_epoch(); + auto epochSeconds = + std::chrono::duration_cast(timeSinceEpoch); + std::chrono::microseconds usecs = + std::chrono::duration_cast(timeSinceEpoch) - + epochSeconds; + time_t unixTimestamp = epochSeconds.count(); + if (!localtime_r(&unixTimestamp, <ime)) { + memset(<ime, 0, sizeof(ltime)); + } + + auto basename = message.getFileBaseName(); + auto headerFormatter = folly::format( + "{}{:02d}{:02d} {:02d}:{:02d}:{:02d}.{:06d} {:5d} {}:{}] ", + getGlogLevelName(message.getLevel())[0], + ltime.tm_mon + 1, + ltime.tm_mday, + ltime.tm_hour, + ltime.tm_min, + ltime.tm_sec, + usecs.count(), + message.getThreadID(), + basename, + message.getLineNumber()); + + // TODO: Support including thread names and thread context info. + + // The fixed portion of the header takes up 31 bytes. + // + // The variable portions that we can't account for here include the line + // number and the thread ID (just in case it is larger than 6 digits long). + // Here we guess that 40 bytes will be long enough to include room for this. + // + // If this still isn't long enough the string will grow as necessary, so the + // code will still be correct, but just slightly less efficient than if we + // had allocated a large enough buffer the first time around. + size_t headerLengthGuess = 40 + basename.size(); + + // Format the data into a buffer. + std::string buffer; + StringPiece msgData{message.getMessage()}; + if (message.containsNewlines()) { + // If there are multiple lines in the log message, add a header + // before each one. + std::string header; + header.reserve(headerLengthGuess); + headerFormatter.appendTo(header); + + // Make a guess at how many lines will be in the message, just to make an + // initial buffer allocation. If the guess is too small then the string + // will reallocate and grow as necessary, it will just be slightly less + // efficient than if we had guessed enough space. + size_t numLinesGuess = 4; + buffer.reserve(((header.size() + 1) * numLinesGuess) + msgData.size()); + + size_t idx = 0; + while (true) { + auto end = msgData.find('\n', idx); + if (end == StringPiece::npos) { + end = msgData.size(); + } + + buffer.append(header); + auto line = msgData.subpiece(idx, end - idx); + buffer.append(line.data(), line.size()); + buffer.push_back('\n'); + + if (end == msgData.size()) { + break; + } + idx = end + 1; + } + } else { + buffer.reserve(headerLengthGuess + msgData.size()); + headerFormatter.appendTo(buffer); + buffer.append(msgData.data(), msgData.size()); + buffer.push_back('\n'); + } + + return buffer; +} +} diff --git a/folly/experimental/logging/GlogStyleFormatter.h b/folly/experimental/logging/GlogStyleFormatter.h new file mode 100644 index 00000000..d732f006 --- /dev/null +++ b/folly/experimental/logging/GlogStyleFormatter.h @@ -0,0 +1,59 @@ +/* + * 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 + +namespace folly { + +/** + * A LogFormatter implementation that produces messages in a format similar to + * that produced by the Google logging library. + * + * The glog message format is: + * + * LmmDD HH:MM:SS.USECS THREAD [THREADNAME] (THREADCTX) FILE:LINE] MSG + * + * L: A 1-character code describing the log level (e.g., E, W, I, V) + * mm: 2-digit month + * DD: 2-digit day + * HH: 2-digit hour, 24-hour format + * MM: 2-digit minute + * SS: 2-digit second + * USECS: 6-digit microseconds + * THREAD: Thread ID + * FILE: Filename (just the last component) + * LINE: Line number + * MSG: The actual log message + * + * [THREADNAME] is the thread name, and is only included if --logthreadnames + * was enabled on the command line. + * + * (THREADCTX) is thread-local log context data, if it has been set. (This is + * a Facebook-specific modification, and is disabled unless --logthreadcontext + * was enabled on the command line.) + * + * Exception information and a custom log prefix may also appear after the + * file name and line number, before the ']' character. + */ +class GlogStyleFormatter : public LogFormatter { + public: + std::string formatMessage( + const LogMessage& message, + const LogCategory* handlerCategory) override; +}; +} diff --git a/folly/experimental/logging/Makefile.am b/folly/experimental/logging/Makefile.am index 69adaf92..c3fc0219 100644 --- a/folly/experimental/logging/Makefile.am +++ b/folly/experimental/logging/Makefile.am @@ -4,6 +4,7 @@ lib_LTLIBRARIES = libfollylogging.la libfollylogging_la_SOURCES = \ AsyncFileWriter.cpp \ + GlogStyleFormatter.cpp \ ImmediateFileWriter.cpp \ LogCategory.cpp \ Logger.cpp \ diff --git a/folly/experimental/logging/test/GlogFormatterTest.cpp b/folly/experimental/logging/test/GlogFormatterTest.cpp new file mode 100644 index 00000000..9f0ad77d --- /dev/null +++ b/folly/experimental/logging/test/GlogFormatterTest.cpp @@ -0,0 +1,179 @@ +/* + * 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 +#include +#include +#include +#include + +using namespace folly; + +namespace { +/** + * Helper function to format a LogMessage using the GlogStyleFormatter. + * + * formatMsg() accepts the timestamp as a plain integer simply to reduce the + * verbosity of the test code. + * + * Note that in this test's main() function we set the timezone to "UTC" + * so that the logged time values will be consistent regardless of the actual + * local time on this host. + */ +std::string formatMsg( + LogLevel level, + StringPiece msg, + StringPiece filename, + unsigned int lineNumber, + // Default timestamp: 2017-04-17 13:45:56.123456 UTC + uint64_t timestampNS = 1492436756123456789ULL) { + LoggerDB db{LoggerDB::TESTING}; + auto* category = db.getCategory("test"); + GlogStyleFormatter formatter; + + std::chrono::system_clock::time_point logTimePoint{ + std::chrono::nanoseconds{timestampNS}}; + LogMessage logMessage{ + category, level, logTimePoint, filename, lineNumber, msg.str()}; + + return formatter.formatMessage(logMessage, category); +} +} // unnamed namespace + +TEST(GlogFormatter, log) { + auto tid = getOSThreadID(); + + // Test a very simple single-line log message + auto expected = folly::sformat( + "W0417 13:45:56.123456 {:5d} myfile.cpp:1234] hello world\n", tid); + EXPECT_EQ( + expected, formatMsg(LogLevel::WARN, "hello world", "myfile.cpp", 1234)); +} + +TEST(GlogFormatter, filename) { + auto tid = getOSThreadID(); + + // Make sure only the file basename gets logged + auto expected = folly::sformat( + "W0417 13:45:56.123456 {:5d} myfile.cpp:1234] hello world\n", tid); + EXPECT_EQ( + expected, + formatMsg( + LogLevel::WARN, + "hello world", + "src/test/logging/code/myfile.cpp", + 1234)); + + // Log a message with a very long file name. + expected = folly::sformat( + "W0417 13:45:56.123456 {:5d} " + "this_is_a_really_long_file_name_that_will_probably_exceed_" + "our_buffer_allocation_guess.cpp:123456789] oh noes\n", + tid); + EXPECT_EQ( + expected, + formatMsg( + LogLevel::WARN, + "oh noes", + "this_is_a_really_long_file_name_that_will_probably_exceed_" + "our_buffer_allocation_guess.cpp", + 123456789)); +} + +TEST(GlogFormatter, multiline) { + auto tid = getOSThreadID(); + std::map formatMap{ + {"tid", folly::to(tid)}}; + + // Log a multi-line message + auto expected = folly::svformat( + "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777] Eeek, a mouse!\n" + "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777] . .\n" + "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777] ( ).( )\n" + "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777] (o o) .-._.'\n" + "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777] ( - )\n" + "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777] mm mm\n" + "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777] \n" + "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777] =============\n", + formatMap); + EXPECT_EQ( + expected, + formatMsg( + LogLevel::DBG9, + "Eeek, a mouse!\n" + " . .\n" + " ( ).( )\n" + " (o o) .-._.'\n" + " ( - )\n" + " mm mm\n" + "\n" + "=============", + "src/rodent.cpp", + 777)); +} + +TEST(GlogFormatter, singleNewline) { + auto tid = getOSThreadID(); + std::map formatMap{ + {"tid", folly::to(tid)}}; + + // Logging a single newline is basically two empty strings. + auto expected = folly::svformat( + "V0417 13:45:56.123456 {tid:>5s} foo.txt:123] \n" + "V0417 13:45:56.123456 {tid:>5s} foo.txt:123] \n", + formatMap); + EXPECT_EQ(expected, formatMsg(LogLevel::DBG9, "\n", "foo.txt", 123)); +} + +TEST(GlogFormatter, unprintableChars) { + auto tid = getOSThreadID(); + + // Unprintable characters should be backslash escaped, as should backslashes. + auto expected = folly::sformat( + "E0417 13:45:56.123456 {:5d} escapes.cpp:97] foo\\x07bar\\x1btest\n", + tid); + EXPECT_EQ( + expected, + formatMsg(LogLevel::ERROR, "foo\abar\x1btest", "escapes.cpp", 97)); + expected = folly::sformat( + "I0417 13:45:56.123456 {:5d} escapes.cpp:98] foo\\\\bar\"test\n", tid); + EXPECT_EQ( + expected, formatMsg(LogLevel::INFO, "foo\\bar\"test", "escapes.cpp", 98)); + expected = folly::sformat( + "C0417 13:45:56.123456 {:5d} escapes.cpp:99] nul\\x00byte\n", tid); + EXPECT_EQ( + expected, + formatMsg( + LogLevel::CRITICAL, std::string("nul\0byte", 8), "escapes.cpp", 99)); +} + +int main(int argc, char* argv[]) { + testing::InitGoogleTest(&argc, argv); + folly::init(&argc, &argv); + + // Some of our tests check timestamps emitted by the formatter. + // Set the timezone to a consistent value so that the tests are not + // affected by the local time of the user running the test. + // + // UTC is the only timezone that we can really rely on to work consistently. + // This will work even in the absence of a proper tzdata installation on the + // local system. + setenv("TZ", "UTC", 1); + + return RUN_ALL_TESTS(); +}