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