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