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
31static const LogTagSet& tagset = LogTagSetMapping<LOG_TAGS(logging, safepoint)>::tagset();
32static const LogDecorators default_decorators;
33
34TEST_VM(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
55TEST_VM(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
76TEST_VM(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)
85TEST_VM(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
125TEST(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, s, ms;
135  int read = sscanf(timestr, "%d-%d-%dT%d:%d:%d.%d", &y, &M, &d, &h, &m, &s, &ms);
136  ASSERT_EQ(7, read) << "Invalid format: " << timestr;
137
138  // Verify reported time & date
139  struct tm reported_time = {0};
140  reported_time.tm_year = y - 1900;
141  reported_time.tm_mon = M - 1;
142  reported_time.tm_mday = d;
143  reported_time.tm_hour = h;
144  reported_time.tm_min = m;
145  reported_time.tm_sec = s;
146  reported_time.tm_isdst = -1; // let mktime deduce DST settings
147  time_t reported_ts = mktime(&reported_time);
148  expected_ts = mktime(localtime(&expected_ts));
149  time_t diff = reported_ts - expected_ts;
150  if (diff < 0) {
151    diff = -diff;
152  }
153  // Allow up to 10 seconds in difference
154  ASSERT_LE(diff, 10) << "Reported time: " << reported_ts << " (" << timestr << ")"
155      << ", expected time: " << expected_ts;
156}
157
158// Test the utctime decoration
159TEST(LogDecorations, iso8601_utctime) {
160  LogDecorators decorator_selection;
161  ASSERT_TRUE(decorator_selection.parse("utctime"));
162  LogDecorations decorations(LogLevel::Info, tagset, decorator_selection);
163
164  const char *timestr = decorations.decoration(LogDecorators::utctime_decorator);
165  time_t expected_ts = time(NULL);
166
167  // Verify format
168  char trailing_character;
169  int y, M, d, h, m, s, ms, offset;
170
171  int read = sscanf(timestr, "%d-%d-%dT%d:%d:%d.%d%c%d", &y, &M, &d, &h, &m, &s, &ms, &trailing_character, &offset);
172
173  ASSERT_EQ(9, read) << "Invalid format: " << timestr;
174
175  // Ensure time is UTC (no offset)
176  ASSERT_EQ('+', trailing_character) << "Invalid trailing character for UTC: "
177          << trailing_character;
178  ASSERT_EQ(0, offset) << "Invalid offset: " << timestr;
179
180  struct tm reported_time = {0};
181  reported_time.tm_year = y - 1900;
182  reported_time.tm_mon = M - 1;
183  reported_time.tm_mday = d;
184  reported_time.tm_hour = h;
185  reported_time.tm_min = m;
186  reported_time.tm_sec = s;
187  reported_time.tm_isdst = 0; // No DST for UTC timestamps
188  time_t reported_ts = mktime(&reported_time);
189  expected_ts = mktime(gmtime(&expected_ts));
190  time_t diff = reported_ts - expected_ts;
191  if (diff < 0) {
192    diff = -diff;
193  }
194  // Allow up to 10 seconds in difference
195  ASSERT_LE(diff, 10) << "Reported time: " << reported_ts << " (" << timestr << ")"
196      << ", expected time: " << expected_ts;
197}
198
199// Test the pid and tid decorations
200TEST(LogDecorations, identifiers) {
201  LogDecorators decorator_selection;
202  ASSERT_TRUE(decorator_selection.parse("pid,tid"));
203  LogDecorations decorations(LogLevel::Info, tagset, decorator_selection);
204
205  struct {
206      intx expected;
207      LogDecorators::Decorator decorator;
208  } ids[] = {
209      { os::current_process_id(), LogDecorators::pid_decorator },
210      { os::current_thread_id(), LogDecorators::tid_decorator },
211  };
212
213  for (uint i = 0; i < ARRAY_SIZE(ids); i++) {
214    const char* reported = decorations.decoration(ids[i].decorator);
215
216    // Verify format
217    const char* str;
218    for (str = reported; isdigit(*str); str++) {
219      // Skip over digits
220    }
221    EXPECT_EQ('\0', *str) << "Should only contain digits";
222
223    // Verify value
224    EXPECT_EQ(ids[i].expected, strtol(reported, NULL, 10));
225  }
226}
227