folly/experimental/logging/test/GlogFormatterTest.cpp

   1 /*
   2  * Copyright 2017-present Facebook, Inc.
   3  *
   4  * Licensed under the Apache License, Version 2.0 (the "License");
   5  * you may not use this file except in compliance with the License.
   6  * You may obtain a copy of the License at
   7  *
   8  *   http://www.apache.org/licenses/LICENSE-2.0
   9  *
  10  * Unless required by applicable law or agreed to in writing, software
  11  * distributed under the License is distributed on an "AS IS" BASIS,
  12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  13  * See the License for the specific language governing permissions and
  14  * limitations under the License.
  15  */
  16 #include <cstdlib>
  17
  18 #include <folly/experimental/logging/GlogStyleFormatter.h>
  19 #include <folly/experimental/logging/LogMessage.h>
  20 #include <folly/experimental/logging/Logger.h>
  21 #include <folly/experimental/logging/LoggerDB.h>
  22 #include <folly/init/Init.h>
  23 #include <folly/portability/GTest.h>
  24 #include <folly/portability/Stdlib.h>
  25
  26 using namespace folly;
  27
  28 namespace {
  29 /**
  30  * Helper function to format a LogMessage using the GlogStyleFormatter.
  31  *
  32  * formatMsg() accepts the timestamp as a plain integer simply to reduce the
  33  * verbosity of the test code.
  34  *
  35  * Note that in this test's main() function we set the timezone to "UTC"
  36  * so that the logged time values will be consistent regardless of the actual
  37  * local time on this host.
  38  */
  39 std::string formatMsg(
  40     LogLevel level,
  41     StringPiece msg,
  42     StringPiece filename,
  43     unsigned int lineNumber,
  44     // Default timestamp: 2017-04-17 13:45:56.123456 UTC
  45     uint64_t timestampNS = 1492436756123456789ULL) {
  46   LoggerDB db{LoggerDB::TESTING};
  47   auto* category = db.getCategory("test");
  48   GlogStyleFormatter formatter;
  49
  50   std::chrono::system_clock::time_point logTimePoint{
  51       std::chrono::duration_cast<std::chrono::system_clock::duration>(
  52           std::chrono::nanoseconds{timestampNS})};
  53   LogMessage logMessage{
  54       category, level, logTimePoint, filename, lineNumber, msg.str()};
  55
  56   return formatter.formatMessage(logMessage, category);
  57 }
  58 } // namespace
  59
  60 TEST(GlogFormatter, log) {
  61   auto tid = getOSThreadID();
  62
  63   // Test a very simple single-line log message
  64   auto expected = folly::sformat(
  65       "W0417 13:45:56.123456 {:5d} myfile.cpp:1234] hello world\n", tid);
  66   EXPECT_EQ(
  67       expected, formatMsg(LogLevel::WARN, "hello world", "myfile.cpp", 1234));
  68 }
  69
  70 TEST(GlogFormatter, filename) {
  71   auto tid = getOSThreadID();
  72
  73   // Make sure only the file basename gets logged
  74   auto expected = folly::sformat(
  75       "W0417 13:45:56.123456 {:5d} myfile.cpp:1234] hello world\n", tid);
  76   EXPECT_EQ(
  77       expected,
  78       formatMsg(
  79           LogLevel::WARN,
  80           "hello world",
  81           "src/test/logging/code/myfile.cpp",
  82           1234));
  83
  84   // Log a message with a very long file name.
  85   expected = folly::sformat(
  86       "W0417 13:45:56.123456 {:5d} "
  87       "this_is_a_really_long_file_name_that_will_probably_exceed_"
  88       "our_buffer_allocation_guess.cpp:123456789] oh noes\n",
  89       tid);
  90   EXPECT_EQ(
  91       expected,
  92       formatMsg(
  93           LogLevel::WARN,
  94           "oh noes",
  95           "this_is_a_really_long_file_name_that_will_probably_exceed_"
  96           "our_buffer_allocation_guess.cpp",
  97           123456789));
  98 }
  99
 100 TEST(GlogFormatter, multiline) {
 101   auto tid = getOSThreadID();
 102   std::map<std::string, std::string> formatMap{
 103       {"tid", folly::to<std::string>(tid)}};
 104
 105   // Log a multi-line message
 106   auto expected = folly::svformat(
 107       "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777] Eeek, a mouse!\n"
 108       "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777]    .   .\n"
 109       "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777]   ( ).( )\n"
 110       "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777]    (o o) .-._.'\n"
 111       "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777]   (  -  )\n"
 112       "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777]    mm mm\n"
 113       "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777] \n"
 114       "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777] =============\n",
 115       formatMap);
 116   EXPECT_EQ(
 117       expected,
 118       formatMsg(
 119           LogLevel::DBG9,
 120           "Eeek, a mouse!\n"
 121           "   .   .\n"
 122           "  ( ).( )\n"
 123           "   (o o) .-._.'\n"
 124           "  (  -  )\n"
 125           "   mm mm\n"
 126           "\n"
 127           "=============",
 128           "src/rodent.cpp",
 129           777));
 130 }
 131
 132 TEST(GlogFormatter, singleNewline) {
 133   auto tid = getOSThreadID();
 134   std::map<std::string, std::string> formatMap{
 135       {"tid", folly::to<std::string>(tid)}};
 136
 137   // Logging a single newline is basically two empty strings.
 138   auto expected = folly::svformat(
 139       "V0417 13:45:56.123456 {tid:>5s} foo.txt:123] \n"
 140       "V0417 13:45:56.123456 {tid:>5s} foo.txt:123] \n",
 141       formatMap);
 142   EXPECT_EQ(expected, formatMsg(LogLevel::DBG9, "\n", "foo.txt", 123));
 143 }
 144
 145 TEST(GlogFormatter, unprintableChars) {
 146   auto tid = getOSThreadID();
 147
 148   // Unprintable characters should be backslash escaped, as should backslashes.
 149   auto expected = folly::sformat(
 150       "E0417 13:45:56.123456 {:5d} escapes.cpp:97] foo\\x07bar\\x1btest\n",
 151       tid);
 152   EXPECT_EQ(
 153       expected,
 154       formatMsg(LogLevel::ERR, "foo\abar\x1btest", "escapes.cpp", 97));
 155   expected = folly::sformat(
 156       "I0417 13:45:56.123456 {:5d} escapes.cpp:98] foo\\\\bar\"test\n", tid);
 157   EXPECT_EQ(
 158       expected, formatMsg(LogLevel::INFO, "foo\\bar\"test", "escapes.cpp", 98));
 159   expected = folly::sformat(
 160       "C0417 13:45:56.123456 {:5d} escapes.cpp:99] nul\\x00byte\n", tid);
 161   EXPECT_EQ(
 162       expected,
 163       formatMsg(
 164           LogLevel::CRITICAL, std::string("nul\0byte", 8), "escapes.cpp", 99));
 165 }
 166
 167 int main(int argc, char* argv[]) {
 168   testing::InitGoogleTest(&argc, argv);
 169   folly::init(&argc, &argv);
 170
 171   // Some of our tests check timestamps emitted by the formatter.
 172   // Set the timezone to a consistent value so that the tests are not
 173   // affected by the local time of the user running the test.
 174   //
 175   // UTC is the only timezone that we can really rely on to work consistently.
 176   // This will work even in the absence of a proper tzdata installation on the
 177   // local system.
 178   setenv("TZ", "UTC", 1);
 179
 180   return RUN_ALL_TESTS();
 181 }