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