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 "logTestFixture.hpp"
26 #include "logTestUtils.inline.hpp"
27 #include "logging/logConfiguration.hpp"
28 #include "logging/logFileStreamOutput.hpp"
29 #include "logging/logLevel.hpp"
30 #include "logging/logOutput.hpp"
31 #include "logging/logTag.hpp"
32 #include "logging/logTagSet.hpp"
33 #include "memory/resourceArea.hpp"
34 #include "unittest.hpp"
35 #include "utilities/ostream.hpp"
36
37 class LogConfigurationTest : public LogTestFixture {
38 protected:
39 static char _all_decorators[256];
40
41 public:
42 static void SetUpTestCase();
43 };
44
45 char LogConfigurationTest::_all_decorators[256];
46
47 // Prepare _all_decorators to contain the full list of decorators (comma separated)
48 void LogConfigurationTest::SetUpTestCase() {
49 char *pos = _all_decorators;
50 for (size_t i = 0; i < LogDecorators::Count; i++) {
51 pos += jio_snprintf(pos, sizeof(_all_decorators) - (pos - _all_decorators), "%s%s",
52 (i == 0 ? "" : ","),
53 LogDecorators::name(static_cast<LogDecorators::Decorator>(i)));
54 }
55 }
56
57 // Check if the given text is included by LogConfiguration::describe()
58 static bool is_described(const char* text) {
59 ResourceMark rm;
60 stringStream ss;
61 LogConfiguration::describe(&ss);
62 return string_contains_substring(ss.as_string(), text);
63 }
64
65 TEST_VM_F(LogConfigurationTest, describe) {
66 ResourceMark rm;
67 stringStream ss;
68 LogConfiguration::describe(&ss);
69 const char* description = ss.as_string();
70
71 // Verify that stdout and stderr are listed by default
72 EXPECT_PRED2(string_contains_substring, description, StdoutLog.name());
73 EXPECT_PRED2(string_contains_substring, description, StderrLog.name());
74
75 // Verify that each tag, level and decorator is listed
76 for (size_t i = 0; i < LogTag::Count; i++) {
77 EXPECT_PRED2(string_contains_substring, description, LogTag::name(static_cast<LogTagType>(i)));
78 }
79 for (size_t i = 0; i < LogLevel::Count; i++) {
80 EXPECT_PRED2(string_contains_substring, description, LogLevel::name(static_cast<LogLevelType>(i)));
81 }
82 for (size_t i = 0; i < LogDecorators::Count; i++) {
83 EXPECT_PRED2(string_contains_substring, description, LogDecorators::name(static_cast<LogDecorators::Decorator>(i)));
84 }
85
86 // Verify that the default configuration is printed
87 char expected_buf[256];
88 int ret = jio_snprintf(expected_buf, sizeof(expected_buf), "=%s", LogLevel::name(LogLevel::Default));
89 ASSERT_NE(-1, ret);
90 EXPECT_PRED2(string_contains_substring, description, expected_buf);
91 EXPECT_PRED2(string_contains_substring, description, "#1: stderr all=off");
92
93 // Verify default decorators are listed
94 LogDecorators default_decorators;
95 expected_buf[0] = '\0';
96 for (size_t i = 0; i < LogDecorators::Count; i++) {
97 LogDecorators::Decorator d = static_cast<LogDecorators::Decorator>(i);
98 if (default_decorators.is_decorator(d)) {
99 ASSERT_LT(strlen(expected_buf), sizeof(expected_buf));
100 ret = jio_snprintf(expected_buf + strlen(expected_buf),
101 sizeof(expected_buf) - strlen(expected_buf),
102 "%s%s",
103 strlen(expected_buf) > 0 ? "," : "",
104 LogDecorators::name(d));
105 ASSERT_NE(-1, ret);
106 }
107 }
108 EXPECT_PRED2(string_contains_substring, description, expected_buf);
109
110 // Add a new output and verify that it gets described after it has been added
111 const char* what = "all=trace";
112 EXPECT_FALSE(is_described(TestLogFileName)) << "Test output already exists!";
113 set_log_config(TestLogFileName, what);
114 EXPECT_TRUE(is_described(TestLogFileName));
115 EXPECT_TRUE(is_described("logging=trace"));
116 }
117
118 // Test updating an existing log output
119 TEST_VM_F(LogConfigurationTest, update_output) {
120 // Update stdout twice, first using it's name, and the second time its index #
121 const char* test_outputs[] = { "stdout", "#0" };
122 for (size_t i = 0; i < ARRAY_SIZE(test_outputs); i++) {
123 set_log_config(test_outputs[i], "all=info");
124
125 // Verify configuration using LogConfiguration::describe
126 EXPECT_TRUE(is_described("#0: stdout"));
127 EXPECT_TRUE(is_described("logging=info"));
128
129 // Verify by iterating over tagsets
130 LogOutput* o = &StdoutLog;
131 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
132 EXPECT_TRUE(ts->has_output(o));
133 EXPECT_TRUE(ts->is_level(LogLevel::Info));
134 EXPECT_FALSE(ts->is_level(LogLevel::Debug));
135 }
136
137 // Now change the level and verify the change propagated
138 set_log_config(test_outputs[i], "all=debug");
139 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
140 EXPECT_TRUE(ts->has_output(o));
141 EXPECT_TRUE(ts->is_level(LogLevel::Debug));
142 EXPECT_FALSE(ts->is_level(LogLevel::Trace));
143 }
144 }
145 }
146
147 // Test adding a new output to the configuration
148 TEST_VM_F(LogConfigurationTest, add_new_output) {
149 const char* what = "all=trace";
150
151 ASSERT_FALSE(is_described(TestLogFileName));
152 set_log_config(TestLogFileName, what);
153
154 // Verify new output using LogConfiguration::describe
155 EXPECT_TRUE(is_described(TestLogFileName));
156 EXPECT_TRUE(is_described("logging=trace"));
157
158 // Also verify by iterating over tagsets, checking levels on tagsets
159 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
160 EXPECT_TRUE(ts->is_level(LogLevel::Trace));
161 }
162 }
163
164 TEST_VM_F(LogConfigurationTest, disable_logging) {
165 // Add TestLogFileName as an output
166 set_log_config(TestLogFileName, "logging=info");
167
168 // Add a second file output
169 char other_file_name[2 * K];
170 jio_snprintf(other_file_name, sizeof(other_file_name), "%s-other", TestLogFileName);
171 set_log_config(other_file_name, "logging=info");
172
173 LogConfiguration::disable_logging();
174
175 // Verify that both file outputs were disabled
176 EXPECT_FALSE(is_described(TestLogFileName));
177 EXPECT_FALSE(is_described(other_file_name));
178 delete_file(other_file_name);
179
180 // Verify that no tagset has logging enabled
181 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
182 EXPECT_FALSE(ts->has_output(&StdoutLog));
183 EXPECT_FALSE(ts->has_output(&StderrLog));
184 EXPECT_FALSE(ts->is_level(LogLevel::Error));
185 }
186 }
187
188 // Test disabling a particular output
189 TEST_VM_F(LogConfigurationTest, disable_output) {
190 // Disable the default configuration for stdout
191 set_log_config("stdout", "all=off");
192
193 // Verify configuration using LogConfiguration::describe
194 EXPECT_TRUE(is_described("#0: stdout all=off"));
195
196 // Verify by iterating over tagsets
197 LogOutput* o = &StdoutLog;
198 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
199 EXPECT_FALSE(ts->has_output(o));
200 EXPECT_FALSE(ts->is_level(LogLevel::Error));
201 }
202
203 // Add a new file output
204 const char* what = "all=debug";
205 set_log_config(TestLogFileName, what);
206 EXPECT_TRUE(is_described(TestLogFileName));
207
208 // Now disable it, verifying it is removed completely
209 set_log_config(TestLogFileName, "all=off");
210 EXPECT_FALSE(is_described(TestLogFileName));
211 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
212 EXPECT_FALSE(ts->is_level(LogLevel::Error));
213 }
214 }
215
216 // Test reconfiguration of the selected decorators for an output
217 TEST_VM_F(LogConfigurationTest, reconfigure_decorators) {
218 // Configure stderr with all decorators
219 set_log_config("stderr", "all=off", _all_decorators);
220 char buf[256];
221 int ret = jio_snprintf(buf, sizeof(buf), "#1: stderr all=off %s", _all_decorators);
222 ASSERT_NE(-1, ret);
223 EXPECT_TRUE(is_described(buf)) << "'" << buf << "' not described after reconfiguration";
224
225 // Now reconfigure logging on stderr with no decorators
226 set_log_config("stderr", "all=off", "none");
227 EXPECT_TRUE(is_described("#1: stderr all=off \n")) << "Expecting no decorators";
228 }
229
230 // Test that invalid options cause configuration errors
231 TEST_VM_F(LogConfigurationTest, invalid_configure_options) {
232 LogConfiguration::disable_logging();
233 const char* invalid_outputs[] = { "#2", "invalidtype=123", ":invalid/path}to*file?" };
234 for (size_t i = 0; i < ARRAY_SIZE(invalid_outputs); i++) {
235 EXPECT_FALSE(set_log_config(invalid_outputs[i], "", "", "", true))
236 << "Accepted invalid output '" << invalid_outputs[i] << "'";
237 }
238 EXPECT_FALSE(LogConfiguration::parse_command_line_arguments("all=invalid_level"));
239 EXPECT_FALSE(LogConfiguration::parse_command_line_arguments("what=invalid"));
240 EXPECT_FALSE(LogConfiguration::parse_command_line_arguments("all::invalid_decorator"));
241 }
242
243 // Test empty configuration options
244 TEST_VM_F(LogConfigurationTest, parse_empty_command_line_arguments) {
245 const char* empty_variations[] = { "", ":", "::", ":::", "::::" };
246 for (size_t i = 0; i < ARRAY_SIZE(empty_variations); i++) {
247 const char* cmdline = empty_variations[i];
248 bool ret = LogConfiguration::parse_command_line_arguments(cmdline);
249 EXPECT_TRUE(ret) << "Error parsing command line arguments '" << cmdline << "'";
250 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
251 EXPECT_EQ(LogLevel::Unspecified, ts->level_for(&StdoutLog));
252 }
253 }
254 }
255
256 // Test basic command line parsing & configuration
257 TEST_VM_F(LogConfigurationTest, parse_command_line_arguments) {
258 // Prepare a command line for logging*=debug on stderr with all decorators
259 int ret;
260 char buf[256];
261 ret = jio_snprintf(buf, sizeof(buf), "logging*=debug:stderr:%s", _all_decorators);
262 ASSERT_NE(-1, ret);
263
264 bool success = LogConfiguration::parse_command_line_arguments(buf);
265 EXPECT_TRUE(success) << "Error parsing valid command line arguments '" << buf << "'";
266 // Ensure the new configuration applied
267 EXPECT_TRUE(is_described("logging=debug"));
268 EXPECT_TRUE(is_described(_all_decorators));
269
270 // Test the configuration of file outputs as well
271 ret = jio_snprintf(buf, sizeof(buf), ":%s", TestLogFileName);
272 ASSERT_NE(-1, ret);
273 EXPECT_TRUE(LogConfiguration::parse_command_line_arguments(buf));
274 }
275
276 // Test split up log configuration arguments
277 TEST_VM_F(LogConfigurationTest, parse_log_arguments) {
278 ResourceMark rm;
279 stringStream ss;
280 // Verify that it's possible to configure each individual tag
281 for (size_t t = 1 /* Skip _NO_TAG */; t < LogTag::Count; t++) {
282 const LogTagType tag = static_cast<LogTagType>(t);
283 EXPECT_TRUE(LogConfiguration::parse_log_arguments("stdout", LogTag::name(tag), "", "", &ss));
284 }
285 // Same for each level
286 for (size_t l = 0; l < LogLevel::Count; l++) {
287 const LogLevelType level = static_cast<LogLevelType>(l);
288 char expected_buf[256];
289 int ret = jio_snprintf(expected_buf, sizeof(expected_buf), "all=%s", LogLevel::name(level));
290 ASSERT_NE(-1, ret);
291 EXPECT_TRUE(LogConfiguration::parse_log_arguments("stderr", expected_buf, "", "", &ss));
292 }
293 // And for each decorator
294 for (size_t d = 0; d < LogDecorators::Count; d++) {
295 const LogDecorators::Decorator decorator = static_cast<LogDecorators::Decorator>(d);
296 EXPECT_TRUE(LogConfiguration::parse_log_arguments("#0", "", LogDecorators::name(decorator), "", &ss));
297 }
298 }
299
300 TEST_VM_F(LogConfigurationTest, configure_stdout) {
301 // Start out with all logging disabled
302 LogConfiguration::disable_logging();
303
304 // Enable 'logging=info', verifying it has been set
305 LogConfiguration::configure_stdout(LogLevel::Info, true, LOG_TAGS(logging));
306 EXPECT_TRUE(log_is_enabled(Info, logging));
307 EXPECT_FALSE(log_is_enabled(Debug, logging));
308 EXPECT_FALSE(log_is_enabled(Info, gc));
309 LogTagSet* logging_ts = &LogTagSetMapping<LOG_TAGS(logging)>::tagset();
310 EXPECT_EQ(LogLevel::Info, logging_ts->level_for(&StdoutLog));
311
312 // Enable 'gc=debug' (no wildcard), verifying no other tags are enabled
313 LogConfiguration::configure_stdout(LogLevel::Debug, true, LOG_TAGS(gc));
314 EXPECT_TRUE(log_is_enabled(Debug, gc));
315 EXPECT_TRUE(log_is_enabled(Info, logging));
316 EXPECT_FALSE(log_is_enabled(Debug, gc, heap));
317 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
318 if (ts->contains(PREFIX_LOG_TAG(gc))) {
319 if (ts->ntags() == 1) {
320 EXPECT_EQ(LogLevel::Debug, ts->level_for(&StdoutLog));
321 } else {
322 EXPECT_EQ(LogLevel::Off, ts->level_for(&StdoutLog));
323 }
324 }
325 }
326
327 // Enable 'gc*=trace' (with wildcard), verifying that all tag combinations with gc are enabled (gc+...)
328 LogConfiguration::configure_stdout(LogLevel::Trace, false, LOG_TAGS(gc));
329 EXPECT_TRUE(log_is_enabled(Trace, gc));
330 EXPECT_TRUE(log_is_enabled(Trace, gc, heap));
331 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
332 if (ts->contains(PREFIX_LOG_TAG(gc))) {
333 EXPECT_EQ(LogLevel::Trace, ts->level_for(&StdoutLog));
334 } else if (ts == logging_ts) {
335 // Previous setting for 'logging' should remain
336 EXPECT_EQ(LogLevel::Info, ts->level_for(&StdoutLog));
337 } else {
338 EXPECT_EQ(LogLevel::Off, ts->level_for(&StdoutLog));
339 }
340 }
341
342 // Disable 'gc*' and 'logging', verifying all logging is properly disabled
343 LogConfiguration::configure_stdout(LogLevel::Off, true, LOG_TAGS(logging));
344 EXPECT_FALSE(log_is_enabled(Error, logging));
345 LogConfiguration::configure_stdout(LogLevel::Off, false, LOG_TAGS(gc));
346 EXPECT_FALSE(log_is_enabled(Error, gc));
347 EXPECT_FALSE(log_is_enabled(Error, gc, heap));
348 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
349 EXPECT_EQ(LogLevel::Off, ts->level_for(&StdoutLog));
350 }
351 }
352
353 static int Test_logconfiguration_subscribe_triggered = 0;
354 static void Test_logconfiguration_subscribe_helper() {
355 Test_logconfiguration_subscribe_triggered++;
356 }
357
358 TEST_VM_F(LogConfigurationTest, subscribe) {
359 ResourceMark rm;
360 Log(logging) log;
361 set_log_config("stdout", "logging*=trace");
362
363 LogConfiguration::register_update_listener(&Test_logconfiguration_subscribe_helper);
364
365 LogConfiguration::parse_log_arguments("stdout", "logging=trace", NULL, NULL, log.error_stream());
366 ASSERT_EQ(1, Test_logconfiguration_subscribe_triggered);
367
368 LogConfiguration::configure_stdout(LogLevel::Debug, true, LOG_TAGS(gc));
369 ASSERT_EQ(2, Test_logconfiguration_subscribe_triggered);
370
371 LogConfiguration::disable_logging();
372 ASSERT_EQ(3, Test_logconfiguration_subscribe_triggered);
373 }
374
375 TEST_VM_F(LogConfigurationTest, parse_invalid_tagset) {
376 static const char* invalid_tagset = "logging+start+exit+safepoint+gc"; // Must not exist for test to function.
377
378 // Make sure warning is produced if one or more configured tagsets are invalid
379 ResourceMark rm;
380 stringStream ss;
381 bool success = LogConfiguration::parse_log_arguments("stdout", invalid_tagset, NULL, NULL, &ss);
382 const char* msg = ss.as_string();
383 EXPECT_TRUE(success) << "Should only cause a warning, not an error";
384 EXPECT_TRUE(string_contains_substring(msg, "No tag set matches selection(s):"));
385 EXPECT_TRUE(string_contains_substring(msg, invalid_tagset));
386 }
387
388 TEST_VM_F(LogConfigurationTest, output_name_normalization) {
389 const char* patterns[] = { "%s", "file=%s", "\"%s\"", "file=\"%s\"" };
390 char buf[1 * K];
391 for (size_t i = 0; i < ARRAY_SIZE(patterns); i++) {
392 int ret = jio_snprintf(buf, sizeof(buf), patterns[i], TestLogFileName);
393 ASSERT_NE(-1, ret);
394 set_log_config(buf, "logging=trace");
395 EXPECT_TRUE(is_described("#2: "));
396 EXPECT_TRUE(is_described(TestLogFileName));
397 EXPECT_FALSE(is_described("#3: "))
398 << "duplicate file output due to incorrect normalization for pattern: " << patterns[i];
399 }
400
401 // Make sure prefixes are ignored when used within quotes
402 // (this should create a log with "file=" in its filename)
403 int ret = jio_snprintf(buf, sizeof(buf), "\"file=%s\"", TestLogFileName);
404 ASSERT_NE(-1, ret);
405 set_log_config(buf, "logging=trace");
406 EXPECT_TRUE(is_described("#3: ")) << "prefix within quotes not ignored as it should be";
407 set_log_config(buf, "all=off");
408
409 // Remove the extra log file created
410 ret = jio_snprintf(buf, sizeof(buf), "file=%s", TestLogFileName);
411 ASSERT_NE(-1, ret);
412 delete_file(buf);
413 }