folly/experimental/logging/test/GlogFormatterTest.cpp

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