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, 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 |
159 | TEST(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 |
200 | TEST(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 | |