1 /*
   2  * Copyright (c) 2016, Oracle and/or its affiliates. All rights reserved.
   3  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
   4  *
   5  * This code is free software; you can redistribute it and/or modify it
   6  * under the terms of the GNU General Public License version 2 only, as
   7  * published by the Free Software Foundation.
   8  *
   9  * This code is distributed in the hope that it will be useful, but WITHOUT
  10  * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
  11  * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
  12  * version 2 for more details (a copy is included in the LICENSE file that
  13  * accompanied this code).
  14  *
  15  * You should have received a copy of the GNU General Public License version
  16  * 2 along with this work; if not, write to the Free Software Foundation,
  17  * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
  18  *
  19  * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
  20  * or visit www.oracle.com if you need additional information or have any
  21  * questions.
  22  *
  23  */
  24 #include "precompiled.hpp"
  25 #include "logging/logDecorations.hpp"
  26 #include "logging/logTagSet.hpp"
  27 #include "runtime/os.hpp"
  28 #include "unittest.hpp"
  29 #include "utilities/globalDefinitions.hpp"
  30 
  31 static const LogTagSet& tagset = LogTagSetMapping<LOG_TAGS(logging, safepoint)>::tagset();
  32 static const LogDecorators default_decorators;
  33 
  34 TEST(LogDecorations, level) {
  35   for (uint l = LogLevel::First; l <= LogLevel::Last; l++) {
  36     LogLevelType level = static_cast<LogLevelType>(l);
  37     // Create a decorations object for the current level
  38     LogDecorations decorations(level, tagset, default_decorators);
  39     // Verify that the level decoration matches the specified level
  40     EXPECT_STREQ(LogLevel::name(level), decorations.decoration(LogDecorators::level_decorator));
  41 
  42     // Test changing level after object creation time
  43     LogLevelType other_level;
  44     if (l != LogLevel::Last) {
  45       other_level = static_cast<LogLevelType>(l + 1);
  46     } else {
  47       other_level = static_cast<LogLevelType>(LogLevel::First);
  48     }
  49     decorations.set_level(other_level);
  50     EXPECT_STREQ(LogLevel::name(other_level), decorations.decoration(LogDecorators::level_decorator))
  51         << "Decoration reports incorrect value after changing the level";
  52   }
  53 }
  54 
  55 TEST(LogDecorations, uptime) {
  56   // Verify the format of the decoration
  57   int a, b;
  58   char decimal_point;
  59   LogDecorations decorations(LogLevel::Info, tagset, default_decorators);
  60   const char* uptime = decorations.decoration(LogDecorators::uptime_decorator);
  61   int read = sscanf(uptime, "%d%c%ds", &a, &decimal_point, &b);
  62   EXPECT_EQ(3, read) << "Invalid uptime decoration: " << uptime;
  63   EXPECT_TRUE(decimal_point == '.' || decimal_point == ',') << "Invalid uptime decoration: " << uptime;
  64 
  65   // Verify that uptime increases
  66   double prev = 0;
  67   for (int i = 0; i < 3; i++) {
  68     os::naked_short_sleep(10);
  69     LogDecorations d(LogLevel::Info, tagset, default_decorators);
  70     double cur = strtod(d.decoration(LogDecorators::uptime_decorator), NULL);
  71     ASSERT_LT(prev, cur);
  72     prev = cur;
  73   }
  74 }
  75 
  76 TEST(LogDecorations, tags) {
  77   char expected_tags[1 * K];
  78   tagset.label(expected_tags, sizeof(expected_tags));
  79   // Verify that the expected tags are included in the tags decoration
  80   LogDecorations decorations(LogLevel::Info, tagset, default_decorators);
  81   EXPECT_STREQ(expected_tags, decorations.decoration(LogDecorators::tags_decorator));
  82 }
  83 
  84 // Test each variation of the different timestamp decorations (ms, ns, uptime ms, uptime ns)
  85 TEST(LogDecorations, timestamps) {
  86   struct {
  87     const LogDecorators::Decorator decorator;
  88     const char* suffix;
  89   } test_decorator[] = {
  90     { LogDecorators::timemillis_decorator, "ms" },
  91     { LogDecorators::uptimemillis_decorator, "ms" },
  92     { LogDecorators::timenanos_decorator, "ns" },
  93     { LogDecorators::uptimenanos_decorator, "ns" }
  94   };
  95 
  96   for (uint i = 0; i < ARRAY_SIZE(test_decorator); i++) {
  97     LogDecorators::Decorator decorator = test_decorator[i].decorator;
  98     LogDecorators decorator_selection;
  99     ASSERT_TRUE(decorator_selection.parse(LogDecorators::name(decorator)));
 100 
 101     // Create decorations with the decorator we want to test included
 102     LogDecorations decorations(LogLevel::Info, tagset, decorator_selection);
 103     const char* decoration = decorations.decoration(decorator);
 104 
 105     // Verify format of timestamp
 106     const char* suffix;
 107     for (suffix = decoration; isdigit(*suffix); suffix++) {
 108       // Skip over digits
 109     }
 110     EXPECT_STREQ(test_decorator[i].suffix, suffix);
 111 
 112     // Verify timestamp values
 113     julong prev = 0;
 114     for (int i = 0; i < 3; i++) {
 115       os::naked_short_sleep(5);
 116       LogDecorations d(LogLevel::Info, tagset, decorator_selection);
 117       julong val = strtoull(d.decoration(decorator), NULL, 10);
 118       ASSERT_LT(prev, val);
 119       prev = val;
 120     }
 121   }
 122 }
 123 
 124 // Test the time decoration
 125 TEST(LogDecorations, iso8601_time) {
 126   LogDecorators decorator_selection;
 127   ASSERT_TRUE(decorator_selection.parse("time"));
 128   LogDecorations decorations(LogLevel::Info, tagset, decorator_selection);
 129 
 130   const char *timestr = decorations.decoration(LogDecorators::time_decorator);
 131   time_t expected_ts = time(NULL);
 132 
 133   // Verify format
 134   int y, M, d, h, m;
 135   double s;
 136   int read = sscanf(timestr, "%d-%d-%dT%d:%d:%lfZ", &y, &M, &d, &h, &m, &s);
 137   ASSERT_EQ(6, read);
 138 
 139   // Verify reported time & date
 140   struct tm reported_time = {0};
 141   reported_time.tm_year = y - 1900;
 142   reported_time.tm_mon = M - 1;
 143   reported_time.tm_mday = d;
 144   reported_time.tm_hour = h;
 145   reported_time.tm_min = m;
 146   reported_time.tm_sec = s;
 147   reported_time.tm_isdst = -1; // let mktime deduce DST settings
 148   time_t reported_ts = mktime(&reported_time);
 149   expected_ts = mktime(localtime(&expected_ts));
 150   time_t diff = reported_ts - expected_ts;
 151   if (diff < 0) {
 152     diff = -diff;
 153   }
 154   // Allow up to 10 seconds in difference
 155   ASSERT_LE(diff, 10) << "Reported time: " << reported_ts << " (" << timestr << ")"
 156       << ", expected time: " << expected_ts;
 157 }
 158 
 159 // Test the pid and tid decorations
 160 TEST(LogDecorations, identifiers) {
 161   LogDecorators decorator_selection;
 162   ASSERT_TRUE(decorator_selection.parse("pid,tid"));
 163   LogDecorations decorations(LogLevel::Info, tagset, decorator_selection);
 164 
 165   struct {
 166       intx expected;
 167       LogDecorators::Decorator decorator;
 168   } ids[] = {
 169       { os::current_process_id(), LogDecorators::pid_decorator },
 170       { os::current_thread_id(), LogDecorators::tid_decorator },
 171   };
 172 
 173   for (uint i = 0; i < ARRAY_SIZE(ids); i++) {
 174     const char* reported = decorations.decoration(ids[i].decorator);
 175 
 176     // Verify format
 177     const char* str;
 178     for (str = reported; isdigit(*str); str++) {
 179       // Skip over digits
 180     }
 181     EXPECT_EQ('\0', *str) << "Should only contain digits";
 182 
 183     // Verify value
 184     EXPECT_EQ(ids[i].expected, strtol(reported, NULL, 10));
 185   }
 186 }