annotate hotspot/test/native/logging/test_logConfiguration.cpp @ 40902:395e1f3ec886

8157948: UL allows same log file with multiple file= Reviewed-by: dholmes, rehn
author mlarsson
date Mon, 29 Aug 2016 14:11:22 +0200
parents b3958b331451
children 9e0c6db4918a
rev   line source
mlarsson@40656 1 /*
mlarsson@40656 2 * Copyright (c) 2016, Oracle and/or its affiliates. All rights reserved.
mlarsson@40656 3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
mlarsson@40656 4 *
mlarsson@40656 5 * This code is free software; you can redistribute it and/or modify it
mlarsson@40656 6 * under the terms of the GNU General Public License version 2 only, as
mlarsson@40656 7 * published by the Free Software Foundation.
mlarsson@40656 8 *
mlarsson@40656 9 * This code is distributed in the hope that it will be useful, but WITHOUT
mlarsson@40656 10 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
mlarsson@40656 11 * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
mlarsson@40656 12 * version 2 for more details (a copy is included in the LICENSE file that
mlarsson@40656 13 * accompanied this code).
mlarsson@40656 14 *
mlarsson@40656 15 * You should have received a copy of the GNU General Public License version
mlarsson@40656 16 * 2 along with this work; if not, write to the Free Software Foundation,
mlarsson@40656 17 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
mlarsson@40656 18 *
mlarsson@40656 19 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
mlarsson@40656 20 * or visit www.oracle.com if you need additional information or have any
mlarsson@40656 21 * questions.
mlarsson@40656 22 *
mlarsson@40656 23 */
mlarsson@40656 24 #include "precompiled.hpp"
mlarsson@40656 25 #include "logTestFixture.hpp"
mlarsson@40656 26 #include "logTestUtils.inline.hpp"
mlarsson@40656 27 #include "logging/logConfiguration.hpp"
mlarsson@40656 28 #include "logging/logLevel.hpp"
mlarsson@40656 29 #include "logging/logOutput.hpp"
mlarsson@40656 30 #include "logging/logTag.hpp"
mlarsson@40656 31 #include "logging/logTagSet.hpp"
mlarsson@40656 32 #include "memory/resourceArea.hpp"
mlarsson@40656 33 #include "unittest.hpp"
mlarsson@40656 34 #include "utilities/ostream.hpp"
mlarsson@40656 35
mlarsson@40656 36 class LogConfigurationTest : public LogTestFixture {
mlarsson@40656 37 protected:
mlarsson@40656 38 static char _all_decorators[256];
mlarsson@40656 39
mlarsson@40656 40 public:
mlarsson@40656 41 static void SetUpTestCase();
mlarsson@40656 42 };
mlarsson@40656 43
mlarsson@40656 44 char LogConfigurationTest::_all_decorators[256];
mlarsson@40656 45
mlarsson@40656 46 // Prepare _all_decorators to contain the full list of decorators (comma separated)
mlarsson@40656 47 void LogConfigurationTest::SetUpTestCase() {
mlarsson@40656 48 char *pos = _all_decorators;
mlarsson@40656 49 for (size_t i = 0; i < LogDecorators::Count; i++) {
mlarsson@40656 50 pos += jio_snprintf(pos, sizeof(_all_decorators) - (pos - _all_decorators), "%s%s",
mlarsson@40656 51 (i == 0 ? "" : ","),
mlarsson@40656 52 LogDecorators::name(static_cast<LogDecorators::Decorator>(i)));
mlarsson@40656 53 }
mlarsson@40656 54 }
mlarsson@40656 55
mlarsson@40656 56 // Check if the given text is included by LogConfiguration::describe()
mlarsson@40656 57 static bool is_described(const char* text) {
mlarsson@40656 58 ResourceMark rm;
mlarsson@40656 59 stringStream ss;
mlarsson@40656 60 LogConfiguration::describe(&ss);
mlarsson@40656 61 return string_contains_substring(ss.as_string(), text);
mlarsson@40656 62 }
mlarsson@40656 63
mlarsson@40656 64 TEST_F(LogConfigurationTest, describe) {
mlarsson@40656 65 ResourceMark rm;
mlarsson@40656 66 stringStream ss;
mlarsson@40656 67 LogConfiguration::describe(&ss);
mlarsson@40656 68 const char* description = ss.as_string();
mlarsson@40656 69
mlarsson@40656 70 // Verify that stdout and stderr are listed by default
mlarsson@40656 71 EXPECT_PRED2(string_contains_substring, description, LogOutput::Stdout->name());
mlarsson@40656 72 EXPECT_PRED2(string_contains_substring, description, LogOutput::Stderr->name());
mlarsson@40656 73
mlarsson@40656 74 // Verify that each tag, level and decorator is listed
mlarsson@40656 75 for (size_t i = 0; i < LogTag::Count; i++) {
mlarsson@40656 76 EXPECT_PRED2(string_contains_substring, description, LogTag::name(static_cast<LogTagType>(i)));
mlarsson@40656 77 }
mlarsson@40656 78 for (size_t i = 0; i < LogLevel::Count; i++) {
mlarsson@40656 79 EXPECT_PRED2(string_contains_substring, description, LogLevel::name(static_cast<LogLevelType>(i)));
mlarsson@40656 80 }
mlarsson@40656 81 for (size_t i = 0; i < LogDecorators::Count; i++) {
mlarsson@40656 82 EXPECT_PRED2(string_contains_substring, description, LogDecorators::name(static_cast<LogDecorators::Decorator>(i)));
mlarsson@40656 83 }
mlarsson@40656 84
mlarsson@40656 85 // Verify that the default configuration is printed
mlarsson@40656 86 char expected_buf[256];
mlarsson@40656 87 int ret = jio_snprintf(expected_buf, sizeof(expected_buf), "=%s", LogLevel::name(LogLevel::Default));
mlarsson@40656 88 ASSERT_NE(-1, ret);
mlarsson@40656 89 EXPECT_PRED2(string_contains_substring, description, expected_buf);
mlarsson@40656 90 EXPECT_PRED2(string_contains_substring, description, "#1: stderr all=off");
mlarsson@40656 91
mlarsson@40656 92 // Verify default decorators are listed
mlarsson@40656 93 LogDecorators default_decorators;
mlarsson@40656 94 expected_buf[0] = '\0';
mlarsson@40656 95 for (size_t i = 0; i < LogDecorators::Count; i++) {
mlarsson@40656 96 LogDecorators::Decorator d = static_cast<LogDecorators::Decorator>(i);
mlarsson@40656 97 if (default_decorators.is_decorator(d)) {
mlarsson@40656 98 ASSERT_LT(strlen(expected_buf), sizeof(expected_buf));
mlarsson@40656 99 ret = jio_snprintf(expected_buf + strlen(expected_buf),
mlarsson@40656 100 sizeof(expected_buf) - strlen(expected_buf),
mlarsson@40656 101 "%s%s",
mlarsson@40656 102 strlen(expected_buf) > 0 ? "," : "",
mlarsson@40656 103 LogDecorators::name(d));
mlarsson@40656 104 ASSERT_NE(-1, ret);
mlarsson@40656 105 }
mlarsson@40656 106 }
mlarsson@40656 107 EXPECT_PRED2(string_contains_substring, description, expected_buf);
mlarsson@40656 108
mlarsson@40656 109 // Add a new output and verify that it gets described after it has been added
mlarsson@40656 110 const char* what = "all=trace";
mlarsson@40656 111 EXPECT_FALSE(is_described(TestLogFileName)) << "Test output already exists!";
mlarsson@40656 112 set_log_config(TestLogFileName, what);
mlarsson@40656 113 EXPECT_TRUE(is_described(TestLogFileName));
mlarsson@40656 114 EXPECT_TRUE(is_described("logging=trace"));
mlarsson@40656 115 }
mlarsson@40656 116
mlarsson@40656 117 // Test updating an existing log output
mlarsson@40656 118 TEST_F(LogConfigurationTest, update_output) {
mlarsson@40656 119 // Update stdout twice, first using it's name, and the second time its index #
mlarsson@40656 120 const char* test_outputs[] = { "stdout", "#0" };
mlarsson@40656 121 for (size_t i = 0; i < ARRAY_SIZE(test_outputs); i++) {
mlarsson@40656 122 set_log_config(test_outputs[i], "all=info");
mlarsson@40656 123
mlarsson@40656 124 // Verify configuration using LogConfiguration::describe
mlarsson@40656 125 EXPECT_TRUE(is_described("#0: stdout"));
mlarsson@40656 126 EXPECT_TRUE(is_described("logging=info"));
mlarsson@40656 127
mlarsson@40656 128 // Verify by iterating over tagsets
mlarsson@40656 129 LogOutput* o = LogOutput::Stdout;
mlarsson@40656 130 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
mlarsson@40656 131 EXPECT_TRUE(ts->has_output(o));
mlarsson@40656 132 EXPECT_TRUE(ts->is_level(LogLevel::Info));
mlarsson@40656 133 EXPECT_FALSE(ts->is_level(LogLevel::Debug));
mlarsson@40656 134 }
mlarsson@40656 135
mlarsson@40656 136 // Now change the level and verify the change propagated
mlarsson@40656 137 set_log_config(test_outputs[i], "all=debug");
mlarsson@40656 138 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
mlarsson@40656 139 EXPECT_TRUE(ts->has_output(o));
mlarsson@40656 140 EXPECT_TRUE(ts->is_level(LogLevel::Debug));
mlarsson@40656 141 EXPECT_FALSE(ts->is_level(LogLevel::Trace));
mlarsson@40656 142 }
mlarsson@40656 143 }
mlarsson@40656 144 }
mlarsson@40656 145
mlarsson@40656 146 // Test adding a new output to the configuration
mlarsson@40656 147 TEST_F(LogConfigurationTest, add_new_output) {
mlarsson@40656 148 const char* what = "all=trace";
mlarsson@40656 149
mlarsson@40656 150 ASSERT_FALSE(is_described(TestLogFileName));
mlarsson@40656 151 set_log_config(TestLogFileName, what);
mlarsson@40656 152
mlarsson@40656 153 // Verify new output using LogConfiguration::describe
mlarsson@40656 154 EXPECT_TRUE(is_described(TestLogFileName));
mlarsson@40656 155 EXPECT_TRUE(is_described("logging=trace"));
mlarsson@40656 156
mlarsson@40656 157 // Also verify by iterating over tagsets, checking levels on tagsets
mlarsson@40656 158 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
mlarsson@40656 159 EXPECT_TRUE(ts->is_level(LogLevel::Trace));
mlarsson@40656 160 }
mlarsson@40656 161 }
mlarsson@40656 162
mlarsson@40656 163 TEST_F(LogConfigurationTest, disable_logging) {
mlarsson@40656 164 // Add TestLogFileName as an output
mlarsson@40656 165 set_log_config(TestLogFileName, "logging=info");
mlarsson@40656 166
mlarsson@40885 167 // Add a second file output
mlarsson@40885 168 char other_file_name[2 * K];
mlarsson@40885 169 jio_snprintf(other_file_name, sizeof(other_file_name), "%s-other", TestLogFileName);
mlarsson@40885 170 set_log_config(other_file_name, "logging=info");
mlarsson@40885 171
mlarsson@40656 172 LogConfiguration::disable_logging();
mlarsson@40656 173
mlarsson@40885 174 // Verify that both file outputs were disabled
mlarsson@40656 175 EXPECT_FALSE(is_described(TestLogFileName));
mlarsson@40885 176 EXPECT_FALSE(is_described(other_file_name));
mlarsson@40885 177 delete_file(other_file_name);
mlarsson@40656 178
mlarsson@40656 179 // Verify that no tagset has logging enabled
mlarsson@40656 180 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
mlarsson@40656 181 EXPECT_FALSE(ts->has_output(LogOutput::Stdout));
mlarsson@40656 182 EXPECT_FALSE(ts->has_output(LogOutput::Stderr));
mlarsson@40656 183 EXPECT_FALSE(ts->is_level(LogLevel::Error));
mlarsson@40656 184 }
mlarsson@40656 185 }
mlarsson@40656 186
mlarsson@40656 187 // Test disabling a particular output
mlarsson@40656 188 TEST_F(LogConfigurationTest, disable_output) {
mlarsson@40656 189 // Disable the default configuration for stdout
mlarsson@40656 190 set_log_config("stdout", "all=off");
mlarsson@40656 191
mlarsson@40656 192 // Verify configuration using LogConfiguration::describe
mlarsson@40656 193 EXPECT_TRUE(is_described("#0: stdout all=off"));
mlarsson@40656 194
mlarsson@40656 195 // Verify by iterating over tagsets
mlarsson@40656 196 LogOutput* o = LogOutput::Stdout;
mlarsson@40656 197 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
mlarsson@40656 198 EXPECT_FALSE(ts->has_output(o));
mlarsson@40656 199 EXPECT_FALSE(ts->is_level(LogLevel::Error));
mlarsson@40656 200 }
mlarsson@40656 201
mlarsson@40656 202 // Add a new file output
mlarsson@40656 203 const char* what = "all=debug";
mlarsson@40656 204 set_log_config(TestLogFileName, what);
mlarsson@40656 205 EXPECT_TRUE(is_described(TestLogFileName));
mlarsson@40656 206
mlarsson@40656 207 // Now disable it, verifying it is removed completely
mlarsson@40656 208 set_log_config(TestLogFileName, "all=off");
mlarsson@40656 209 EXPECT_FALSE(is_described(TestLogFileName));
mlarsson@40656 210 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
mlarsson@40656 211 EXPECT_FALSE(ts->is_level(LogLevel::Error));
mlarsson@40656 212 }
mlarsson@40656 213 }
mlarsson@40656 214
mlarsson@40656 215 // Test reconfiguration of the selected decorators for an output
mlarsson@40656 216 TEST_F(LogConfigurationTest, reconfigure_decorators) {
mlarsson@40656 217 // Configure stderr with all decorators
mlarsson@40656 218 set_log_config("stderr", "all=off", _all_decorators);
mlarsson@40656 219 char buf[256];
mlarsson@40656 220 int ret = jio_snprintf(buf, sizeof(buf), "#1: stderr all=off %s", _all_decorators);
mlarsson@40656 221 ASSERT_NE(-1, ret);
mlarsson@40656 222 EXPECT_TRUE(is_described(buf)) << "'" << buf << "' not described after reconfiguration";
mlarsson@40656 223
mlarsson@40656 224 // Now reconfigure logging on stderr with no decorators
mlarsson@40656 225 set_log_config("stderr", "all=off", "none");
mlarsson@40656 226 EXPECT_TRUE(is_described("#1: stderr all=off \n")) << "Expecting no decorators";
mlarsson@40656 227 }
mlarsson@40656 228
mlarsson@40656 229 // Test that invalid options cause configuration errors
mlarsson@40656 230 TEST_F(LogConfigurationTest, invalid_configure_options) {
mlarsson@40656 231 LogConfiguration::disable_logging();
mlarsson@40656 232 const char* invalid_outputs[] = { "#2", "invalidtype=123", ":invalid/path}to*file?" };
mlarsson@40656 233 for (size_t i = 0; i < ARRAY_SIZE(invalid_outputs); i++) {
mlarsson@40656 234 EXPECT_FALSE(set_log_config(invalid_outputs[i], "", "", "", true))
mlarsson@40656 235 << "Accepted invalid output '" << invalid_outputs[i] << "'";
mlarsson@40656 236 }
mlarsson@40656 237 EXPECT_FALSE(LogConfiguration::parse_command_line_arguments("all=invalid_level"));
mlarsson@40656 238 EXPECT_FALSE(LogConfiguration::parse_command_line_arguments("what=invalid"));
mlarsson@40656 239 EXPECT_FALSE(LogConfiguration::parse_command_line_arguments("all::invalid_decorator"));
mlarsson@40656 240 }
mlarsson@40656 241
mlarsson@40656 242 // Test empty configuration options
mlarsson@40656 243 TEST_F(LogConfigurationTest, parse_empty_command_line_arguments) {
mlarsson@40656 244 const char* empty_variations[] = { "", ":", "::", ":::", "::::" };
mlarsson@40656 245 for (size_t i = 0; i < ARRAY_SIZE(empty_variations); i++) {
mlarsson@40656 246 const char* cmdline = empty_variations[i];
mlarsson@40656 247 bool ret = LogConfiguration::parse_command_line_arguments(cmdline);
mlarsson@40656 248 EXPECT_TRUE(ret) << "Error parsing command line arguments '" << cmdline << "'";
mlarsson@40656 249 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
mlarsson@40656 250 EXPECT_EQ(LogLevel::Unspecified, ts->level_for(LogOutput::Stdout));
mlarsson@40656 251 }
mlarsson@40656 252 }
mlarsson@40656 253 }
mlarsson@40656 254
mlarsson@40656 255 // Test basic command line parsing & configuration
mlarsson@40656 256 TEST_F(LogConfigurationTest, parse_command_line_arguments) {
mlarsson@40656 257 // Prepare a command line for logging*=debug on stderr with all decorators
mlarsson@40656 258 int ret;
mlarsson@40656 259 char buf[256];
mlarsson@40656 260 ret = jio_snprintf(buf, sizeof(buf), "logging*=debug:stderr:%s", _all_decorators);
mlarsson@40656 261 ASSERT_NE(-1, ret);
mlarsson@40656 262
mlarsson@40656 263 bool success = LogConfiguration::parse_command_line_arguments(buf);
mlarsson@40656 264 EXPECT_TRUE(success) << "Error parsing valid command line arguments '" << buf << "'";
mlarsson@40656 265 // Ensure the new configuration applied
mlarsson@40656 266 EXPECT_TRUE(is_described("logging=debug"));
mlarsson@40656 267 EXPECT_TRUE(is_described(_all_decorators));
mlarsson@40656 268
mlarsson@40656 269 // Test the configuration of file outputs as well
mlarsson@40656 270 ret = jio_snprintf(buf, sizeof(buf), ":%s", TestLogFileName);
mlarsson@40656 271 ASSERT_NE(-1, ret);
mlarsson@40656 272 EXPECT_TRUE(LogConfiguration::parse_command_line_arguments(buf));
mlarsson@40656 273 }
mlarsson@40656 274
mlarsson@40656 275 // Test split up log configuration arguments
mlarsson@40656 276 TEST_F(LogConfigurationTest, parse_log_arguments) {
mlarsson@40656 277 ResourceMark rm;
mlarsson@40656 278 stringStream ss;
mlarsson@40656 279 // Verify that it's possible to configure each individual tag
mlarsson@40656 280 for (size_t t = 1 /* Skip _NO_TAG */; t < LogTag::Count; t++) {
mlarsson@40656 281 const LogTagType tag = static_cast<LogTagType>(t);
mlarsson@40656 282 EXPECT_TRUE(LogConfiguration::parse_log_arguments("stdout", LogTag::name(tag), "", "", &ss));
mlarsson@40656 283 }
mlarsson@40656 284 // Same for each level
mlarsson@40656 285 for (size_t l = 0; l < LogLevel::Count; l++) {
mlarsson@40656 286 const LogLevelType level = static_cast<LogLevelType>(l);
mlarsson@40656 287 char expected_buf[256];
mlarsson@40656 288 int ret = jio_snprintf(expected_buf, sizeof(expected_buf), "all=%s", LogLevel::name(level));
mlarsson@40656 289 ASSERT_NE(-1, ret);
mlarsson@40656 290 EXPECT_TRUE(LogConfiguration::parse_log_arguments("stderr", expected_buf, "", "", &ss));
mlarsson@40656 291 }
mlarsson@40656 292 // And for each decorator
mlarsson@40656 293 for (size_t d = 0; d < LogDecorators::Count; d++) {
mlarsson@40656 294 const LogDecorators::Decorator decorator = static_cast<LogDecorators::Decorator>(d);
mlarsson@40656 295 EXPECT_TRUE(LogConfiguration::parse_log_arguments("#0", "", LogDecorators::name(decorator), "", &ss));
mlarsson@40656 296 }
mlarsson@40656 297 }
mlarsson@40884 298
mlarsson@40884 299 TEST_F(LogConfigurationTest, parse_invalid_tagset) {
mlarsson@40884 300 static const char* invalid_tagset = "logging+start+exit+safepoint+gc"; // Must not exist for test to function.
mlarsson@40884 301
mlarsson@40884 302 // Make sure warning is produced if one or more configured tagsets are invalid
mlarsson@40884 303 ResourceMark rm;
mlarsson@40884 304 stringStream ss;
mlarsson@40884 305 bool success = LogConfiguration::parse_log_arguments("stdout", invalid_tagset, NULL, NULL, &ss);
mlarsson@40884 306 const char* msg = ss.as_string();
mlarsson@40884 307 EXPECT_TRUE(success) << "Should only cause a warning, not an error";
mlarsson@40884 308 EXPECT_TRUE(string_contains_substring(msg, "No tag set matches selection(s):"));
mlarsson@40884 309 EXPECT_TRUE(string_contains_substring(msg, invalid_tagset));
mlarsson@40884 310 }
mlarsson@40902 311
mlarsson@40902 312 TEST_F(LogConfigurationTest, output_name_normalization) {
mlarsson@40902 313 const char* patterns[] = { "%s", "file=%s", "\"%s\"", "file=\"%s\"" };
mlarsson@40902 314 char buf[1 * K];
mlarsson@40902 315 for (size_t i = 0; i < ARRAY_SIZE(patterns); i++) {
mlarsson@40902 316 int ret = jio_snprintf(buf, sizeof(buf), patterns[i], TestLogFileName);
mlarsson@40902 317 ASSERT_NE(-1, ret);
mlarsson@40902 318 set_log_config(buf, "logging=trace");
mlarsson@40902 319 EXPECT_TRUE(is_described("#2: "));
mlarsson@40902 320 EXPECT_TRUE(is_described(TestLogFileName));
mlarsson@40902 321 EXPECT_FALSE(is_described("#3: "))
mlarsson@40902 322 << "duplicate file output due to incorrect normalization for pattern: " << patterns[i];
mlarsson@40902 323 }
mlarsson@40902 324
mlarsson@40902 325 // Make sure prefixes are ignored when used within quotes
mlarsson@40902 326 // (this should create a log with "file=" in its filename)
mlarsson@40902 327 int ret = jio_snprintf(buf, sizeof(buf), "\"file=%s\"", TestLogFileName);
mlarsson@40902 328 ASSERT_NE(-1, ret);
mlarsson@40902 329 set_log_config(buf, "logging=trace");
mlarsson@40902 330 EXPECT_TRUE(is_described("#3: ")) << "prefix within quotes not ignored as it should be";
mlarsson@40902 331 set_log_config(buf, "all=off");
mlarsson@40902 332
mlarsson@40902 333 // Remove the extra log file created
mlarsson@40902 334 ret = jio_snprintf(buf, sizeof(buf), "file=%s", TestLogFileName);
mlarsson@40902 335 ASSERT_NE(-1, ret);
mlarsson@40902 336 delete_file(buf);
mlarsson@40902 337 }