1 /* 2 * Copyright (c) 2016, 2017, 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 "prims/jvm.h" 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("logging=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("logging=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("logging=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 \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 } 243 244 // Test empty configuration options 245 TEST_VM_F(LogConfigurationTest, parse_empty_command_line_arguments) { 246 const char* empty_variations[] = { "", ":", "::", ":::", "::::" }; 247 for (size_t i = 0; i < ARRAY_SIZE(empty_variations); i++) { 248 const char* cmdline = empty_variations[i]; 249 bool ret = LogConfiguration::parse_command_line_arguments(cmdline); 250 EXPECT_TRUE(ret) << "Error parsing command line arguments '" << cmdline << "'"; 251 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) { 252 EXPECT_EQ(LogLevel::Unspecified, ts->level_for(&StdoutLog)); 253 } 254 } 255 } 256 257 // Test basic command line parsing & configuration 258 TEST_VM_F(LogConfigurationTest, parse_command_line_arguments) { 259 // Prepare a command line for logging*=debug on stderr with all decorators 260 int ret; 261 char buf[256]; 262 ret = jio_snprintf(buf, sizeof(buf), "logging*=debug:stderr:%s", _all_decorators); 263 ASSERT_NE(-1, ret); 264 265 bool success = LogConfiguration::parse_command_line_arguments(buf); 266 EXPECT_TRUE(success) << "Error parsing valid command line arguments '" << buf << "'"; 267 // Ensure the new configuration applied 268 EXPECT_TRUE(is_described("logging=debug")); 269 EXPECT_TRUE(is_described(_all_decorators)); 270 271 // Test the configuration of file outputs as well 272 ret = jio_snprintf(buf, sizeof(buf), ":%s", TestLogFileName); 273 ASSERT_NE(-1, ret); 274 EXPECT_TRUE(LogConfiguration::parse_command_line_arguments(buf)); 275 } 276 277 // Test split up log configuration arguments 278 TEST_VM_F(LogConfigurationTest, parse_log_arguments) { 279 ResourceMark rm; 280 stringStream ss; 281 // Verify that it's possible to configure each individual tag 282 for (size_t t = 1 /* Skip _NO_TAG */; t < LogTag::Count; t++) { 283 const LogTagType tag = static_cast<LogTagType>(t); 284 EXPECT_TRUE(LogConfiguration::parse_log_arguments("stdout", LogTag::name(tag), "", "", &ss)); 285 } 286 // Same for each level 287 for (size_t l = 0; l < LogLevel::Count; l++) { 288 const LogLevelType level = static_cast<LogLevelType>(l); 289 char expected_buf[256]; 290 int ret = jio_snprintf(expected_buf, sizeof(expected_buf), "all=%s", LogLevel::name(level)); 291 ASSERT_NE(-1, ret); 292 EXPECT_TRUE(LogConfiguration::parse_log_arguments("stderr", expected_buf, "", "", &ss)); 293 } 294 // And for each decorator 295 for (size_t d = 0; d < LogDecorators::Count; d++) { 296 const LogDecorators::Decorator decorator = static_cast<LogDecorators::Decorator>(d); 297 EXPECT_TRUE(LogConfiguration::parse_log_arguments("#0", "", LogDecorators::name(decorator), "", &ss)); 298 } 299 } 300 301 TEST_VM_F(LogConfigurationTest, configure_stdout) { 302 // Start out with all logging disabled 303 LogConfiguration::disable_logging(); 304 305 // Enable 'logging=info', verifying it has been set 306 LogConfiguration::configure_stdout(LogLevel::Info, true, LOG_TAGS(logging)); 307 EXPECT_TRUE(log_is_enabled(Info, logging)); 308 EXPECT_FALSE(log_is_enabled(Debug, logging)); 309 EXPECT_FALSE(log_is_enabled(Info, gc)); 310 LogTagSet* logging_ts = &LogTagSetMapping<LOG_TAGS(logging)>::tagset(); 311 EXPECT_EQ(LogLevel::Info, logging_ts->level_for(&StdoutLog)); 312 313 // Enable 'gc=debug' (no wildcard), verifying no other tags are enabled 314 LogConfiguration::configure_stdout(LogLevel::Debug, true, LOG_TAGS(gc)); 315 EXPECT_TRUE(log_is_enabled(Debug, gc)); 316 EXPECT_TRUE(log_is_enabled(Info, logging)); 317 EXPECT_FALSE(log_is_enabled(Debug, gc, heap)); 318 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) { 319 if (ts->contains(PREFIX_LOG_TAG(gc))) { 320 if (ts->ntags() == 1) { 321 EXPECT_EQ(LogLevel::Debug, ts->level_for(&StdoutLog)); 322 } else { 323 EXPECT_EQ(LogLevel::Off, ts->level_for(&StdoutLog)); 324 } 325 } 326 } 327 328 // Enable 'gc*=trace' (with wildcard), verifying that all tag combinations with gc are enabled (gc+...) 329 LogConfiguration::configure_stdout(LogLevel::Trace, false, LOG_TAGS(gc)); 330 EXPECT_TRUE(log_is_enabled(Trace, gc)); 331 EXPECT_TRUE(log_is_enabled(Trace, gc, heap)); 332 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) { 333 if (ts->contains(PREFIX_LOG_TAG(gc))) { 334 EXPECT_EQ(LogLevel::Trace, ts->level_for(&StdoutLog)); 335 } else if (ts == logging_ts) { 336 // Previous setting for 'logging' should remain 337 EXPECT_EQ(LogLevel::Info, ts->level_for(&StdoutLog)); 338 } else { 339 EXPECT_EQ(LogLevel::Off, ts->level_for(&StdoutLog)); 340 } 341 } 342 343 // Disable 'gc*' and 'logging', verifying all logging is properly disabled 344 LogConfiguration::configure_stdout(LogLevel::Off, true, LOG_TAGS(logging)); 345 EXPECT_FALSE(log_is_enabled(Error, logging)); 346 LogConfiguration::configure_stdout(LogLevel::Off, false, LOG_TAGS(gc)); 347 EXPECT_FALSE(log_is_enabled(Error, gc)); 348 EXPECT_FALSE(log_is_enabled(Error, gc, heap)); 349 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) { 350 EXPECT_EQ(LogLevel::Off, ts->level_for(&StdoutLog)); 351 } 352 } 353 354 static int Test_logconfiguration_subscribe_triggered = 0; 355 static void Test_logconfiguration_subscribe_helper() { 356 Test_logconfiguration_subscribe_triggered++; 357 } 358 359 TEST_VM_F(LogConfigurationTest, subscribe) { 360 ResourceMark rm; 361 Log(logging) log; 362 set_log_config("stdout", "logging*=trace"); 363 364 LogConfiguration::register_update_listener(&Test_logconfiguration_subscribe_helper); 365 366 LogStream ls(log.error()); 367 LogConfiguration::parse_log_arguments("stdout", "logging=trace", NULL, NULL, &ls); 368 ASSERT_EQ(1, Test_logconfiguration_subscribe_triggered); 369 370 LogConfiguration::configure_stdout(LogLevel::Debug, true, LOG_TAGS(gc)); 371 ASSERT_EQ(2, Test_logconfiguration_subscribe_triggered); 372 373 LogConfiguration::disable_logging(); 374 ASSERT_EQ(3, Test_logconfiguration_subscribe_triggered); 375 } 376 377 TEST_VM_F(LogConfigurationTest, parse_invalid_tagset) { 378 static const char* invalid_tagset = "logging+start+exit+safepoint+gc"; // Must not exist for test to function. 379 380 // Make sure warning is produced if one or more configured tagsets are invalid 381 ResourceMark rm; 382 stringStream ss; 383 bool success = LogConfiguration::parse_log_arguments("stdout", invalid_tagset, NULL, NULL, &ss); 384 const char* msg = ss.as_string(); 385 EXPECT_TRUE(success) << "Should only cause a warning, not an error"; 386 EXPECT_TRUE(string_contains_substring(msg, "No tag set matches selection(s):")); 387 EXPECT_TRUE(string_contains_substring(msg, invalid_tagset)); 388 } 389 390 TEST_VM_F(LogConfigurationTest, output_name_normalization) { 391 const char* patterns[] = { "%s", "file=%s", "\"%s\"", "file=\"%s\"" }; 392 char buf[1 * K]; 393 for (size_t i = 0; i < ARRAY_SIZE(patterns); i++) { 394 int ret = jio_snprintf(buf, sizeof(buf), patterns[i], TestLogFileName); 395 ASSERT_NE(-1, ret); 396 set_log_config(buf, "logging=trace"); 397 EXPECT_TRUE(is_described("#2: ")); 398 EXPECT_TRUE(is_described(TestLogFileName)); 399 EXPECT_FALSE(is_described("#3: ")) 400 << "duplicate file output due to incorrect normalization for pattern: " << patterns[i]; 401 } 402 403 // Make sure prefixes are ignored when used within quotes 404 // (this should create a log with "file=" in its filename) 405 int ret = jio_snprintf(buf, sizeof(buf), "\"file=%s\"", TestLogFileName); 406 ASSERT_NE(-1, ret); 407 set_log_config(buf, "logging=trace"); 408 EXPECT_TRUE(is_described("#3: ")) << "prefix within quotes not ignored as it should be"; 409 set_log_config(buf, "all=off"); 410 411 // Remove the extra log file created 412 ret = jio_snprintf(buf, sizeof(buf), "file=%s", TestLogFileName); 413 ASSERT_NE(-1, ret); 414 delete_file(buf); 415 }