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 "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("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 }