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_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
55 TEST_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
76 TEST_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)
85 TEST_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
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:%lf", &y, &M, &d, &h, &m, &s);
137 ASSERT_EQ(6, read) << "Invalid format: " << timestr;
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 utctime decoration
160 TEST(LogDecorations, iso8601_utctime) {
161 LogDecorators decorator_selection;
162 ASSERT_TRUE(decorator_selection.parse("utctime"));
163 LogDecorations decorations(LogLevel::Info, tagset, decorator_selection);
164
165 const char *timestr = decorations.decoration(LogDecorators::utctime_decorator);
166 time_t expected_ts = time(NULL);
167
168 // Verify format
169 char trailing_character;
170 int y, M, d, h, m, offset;
171 double s;
172 int read = sscanf(timestr, "%d-%d-%dT%d:%d:%lf%c%d", &y, &M, &d, &h, &m, &s, &trailing_character, &offset);
173 ASSERT_GT(read, 7) << "Invalid format: " << timestr;
174
175 // Ensure time is UTC (no offset)
176 if (trailing_character == '+') {
177 ASSERT_EQ(0, offset) << "Invalid offset: " << timestr;
178 } else {
179 ASSERT_EQ('Z', trailing_character) << "Invalid offset: " << timestr;
180 }
181
182 struct tm reported_time = {0};
183 reported_time.tm_year = y - 1900;
184 reported_time.tm_mon = M - 1;
185 reported_time.tm_mday = d;
186 reported_time.tm_hour = h;
187 reported_time.tm_min = m;
188 reported_time.tm_sec = s;
189 reported_time.tm_isdst = 0; // No DST for UTC timestamps
190 time_t reported_ts = mktime(&reported_time);
191 expected_ts = mktime(gmtime(&expected_ts));
192 time_t diff = reported_ts - expected_ts;
193 if (diff < 0) {
194 diff = -diff;
195 }
196 // Allow up to 10 seconds in difference
197 ASSERT_LE(diff, 10) << "Reported time: " << reported_ts << " (" << timestr << ")"
198 << ", expected time: " << expected_ts;
199 }
200
201 // Test the pid and tid decorations
202 TEST(LogDecorations, identifiers) {
203 LogDecorators decorator_selection;
204 ASSERT_TRUE(decorator_selection.parse("pid,tid"));
205 LogDecorations decorations(LogLevel::Info, tagset, decorator_selection);
206
207 struct {
208 intx expected;
209 LogDecorators::Decorator decorator;
210 } ids[] = {
211 { os::current_process_id(), LogDecorators::pid_decorator },
212 { os::current_thread_id(), LogDecorators::tid_decorator },
213 };
214
215 for (uint i = 0; i < ARRAY_SIZE(ids); i++) {
216 const char* reported = decorations.decoration(ids[i].decorator);
217
218 // Verify format
219 const char* str;
220 for (str = reported; isdigit(*str); str++) {
221 // Skip over digits
222 }
223 EXPECT_EQ('\0', *str) << "Should only contain digits";
224
225 // Verify value
226 EXPECT_EQ(ids[i].expected, strtol(reported, NULL, 10));
227 }
228 }