Path: blob/master/test/hotspot/gtest/logging/test_logConfiguration.cpp
64438 views
/*1* Copyright (c) 2016, 2022, Oracle and/or its affiliates. All rights reserved.2* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.3*4* This code is free software; you can redistribute it and/or modify it5* under the terms of the GNU General Public License version 2 only, as6* published by the Free Software Foundation.7*8* This code is distributed in the hope that it will be useful, but WITHOUT9* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or10* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License11* version 2 for more details (a copy is included in the LICENSE file that12* accompanied this code).13*14* You should have received a copy of the GNU General Public License version15* 2 along with this work; if not, write to the Free Software Foundation,16* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.17*18* Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA19* or visit www.oracle.com if you need additional information or have any20* questions.21*/2223#include "precompiled.hpp"24#include "jvm.h"25#include "concurrentTestRunner.inline.hpp"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"3738class LogConfigurationTest : public LogTestFixture {39protected:40static char _all_decorators[256];4142public:43static void SetUpTestCase();44};4546char LogConfigurationTest::_all_decorators[256];4748// Prepare _all_decorators to contain the full list of decorators (comma separated)49void LogConfigurationTest::SetUpTestCase() {50char *pos = _all_decorators;51for (size_t i = 0; i < LogDecorators::Count; i++) {52pos += jio_snprintf(pos, sizeof(_all_decorators) - (pos - _all_decorators), "%s%s",53(i == 0 ? "" : ","),54LogDecorators::name(static_cast<LogDecorators::Decorator>(i)));55}56}5758// Check if the given text is included by LogConfiguration::describe()59static bool is_described(const char* text) {60ResourceMark rm;61stringStream ss;62LogConfiguration::describe(&ss);63return string_contains_substring(ss.as_string(), text);64}6566TEST_VM_F(LogConfigurationTest, describe) {67ResourceMark rm;68stringStream ss;69LogConfiguration::describe(&ss);70const char* description = ss.as_string();7172// Verify that stdout and stderr are listed by default73EXPECT_PRED2(string_contains_substring, description, StdoutLog.name());74EXPECT_PRED2(string_contains_substring, description, StderrLog.name());7576// Verify that each tag, level and decorator is listed77for (size_t i = 0; i < LogTag::Count; i++) {78EXPECT_PRED2(string_contains_substring, description, LogTag::name(static_cast<LogTagType>(i)));79}80for (size_t i = 0; i < LogLevel::Count; i++) {81EXPECT_PRED2(string_contains_substring, description, LogLevel::name(static_cast<LogLevelType>(i)));82}83for (size_t i = 0; i < LogDecorators::Count; i++) {84EXPECT_PRED2(string_contains_substring, description, LogDecorators::name(static_cast<LogDecorators::Decorator>(i)));85}8687// Verify that the default configuration is printed88char expected_buf[256];89int ret = jio_snprintf(expected_buf, sizeof(expected_buf), "=%s", LogLevel::name(LogLevel::Default));90ASSERT_NE(-1, ret);91EXPECT_PRED2(string_contains_substring, description, expected_buf);92EXPECT_PRED2(string_contains_substring, description, "#1: stderr all=off");9394// Verify default decorators are listed95LogDecorators default_decorators;96expected_buf[0] = '\0';97for (size_t i = 0; i < LogDecorators::Count; i++) {98LogDecorators::Decorator d = static_cast<LogDecorators::Decorator>(i);99if (default_decorators.is_decorator(d)) {100ASSERT_LT(strlen(expected_buf), sizeof(expected_buf));101ret = jio_snprintf(expected_buf + strlen(expected_buf),102sizeof(expected_buf) - strlen(expected_buf),103"%s%s",104strlen(expected_buf) > 0 ? "," : "",105LogDecorators::name(d));106ASSERT_NE(-1, ret);107}108}109EXPECT_PRED2(string_contains_substring, description, expected_buf);110111// Add a new output and verify that it gets described after it has been added112const char* what = "all=trace";113EXPECT_FALSE(is_described(TestLogFileName)) << "Test output already exists!";114set_log_config(TestLogFileName, what);115EXPECT_TRUE(is_described(TestLogFileName));116EXPECT_TRUE(is_described("all=trace"));117}118119// Test updating an existing log output120TEST_VM_F(LogConfigurationTest, update_output) {121// Update stdout twice, first using it's name, and the second time its index #122const char* test_outputs[] = { "stdout", "#0" };123for (size_t i = 0; i < ARRAY_SIZE(test_outputs); i++) {124set_log_config(test_outputs[i], "all=info");125126// Verify configuration using LogConfiguration::describe127EXPECT_TRUE(is_described("#0: stdout"));128EXPECT_TRUE(is_described("all=info"));129130// Verify by iterating over tagsets131LogOutput* o = &StdoutLog;132for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {133EXPECT_TRUE(ts->has_output(o));134EXPECT_TRUE(ts->is_level(LogLevel::Info));135EXPECT_FALSE(ts->is_level(LogLevel::Debug));136}137138// Now change the level and verify the change propagated139set_log_config(test_outputs[i], "all=debug");140for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {141EXPECT_TRUE(ts->has_output(o));142EXPECT_TRUE(ts->is_level(LogLevel::Debug));143EXPECT_FALSE(ts->is_level(LogLevel::Trace));144}145}146}147148// Test adding a new output to the configuration149TEST_VM_F(LogConfigurationTest, add_new_output) {150const char* what = "all=trace";151152ASSERT_FALSE(is_described(TestLogFileName));153set_log_config(TestLogFileName, what);154155// Verify new output using LogConfiguration::describe156EXPECT_TRUE(is_described(TestLogFileName));157EXPECT_TRUE(is_described("all=trace"));158159// Also verify by iterating over tagsets, checking levels on tagsets160for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {161EXPECT_TRUE(ts->is_level(LogLevel::Trace));162}163}164165TEST_VM_F(LogConfigurationTest, disable_logging) {166// Add TestLogFileName as an output167set_log_config(TestLogFileName, "logging=info");168169// Add a second file output170char other_file_name[2 * K];171jio_snprintf(other_file_name, sizeof(other_file_name), "%s-other", TestLogFileName);172set_log_config(other_file_name, "logging=info");173174LogConfiguration::disable_logging();175176// Verify that both file outputs were disabled177EXPECT_FALSE(is_described(TestLogFileName));178EXPECT_FALSE(is_described(other_file_name));179delete_file(other_file_name);180181// Verify that no tagset has logging enabled182for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {183EXPECT_FALSE(ts->has_output(&StdoutLog));184EXPECT_FALSE(ts->has_output(&StderrLog));185EXPECT_FALSE(ts->is_level(LogLevel::Error));186}187}188189// Test disabling a particular output190TEST_VM_F(LogConfigurationTest, disable_output) {191// Disable the default configuration for stdout192set_log_config("stdout", "all=off");193194// Verify configuration using LogConfiguration::describe195EXPECT_TRUE(is_described("#0: stdout all=off"));196197// Verify by iterating over tagsets198LogOutput* o = &StdoutLog;199for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {200EXPECT_FALSE(ts->has_output(o));201EXPECT_FALSE(ts->is_level(LogLevel::Error));202}203204// Add a new file output205const char* what = "all=debug";206set_log_config(TestLogFileName, what);207EXPECT_TRUE(is_described(TestLogFileName));208209// Now disable it, verifying it is removed completely210set_log_config(TestLogFileName, "all=off");211EXPECT_FALSE(is_described(TestLogFileName));212for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {213EXPECT_FALSE(ts->is_level(LogLevel::Error));214}215}216217// Test reconfiguration of the selected decorators for an output218TEST_VM_F(LogConfigurationTest, reconfigure_decorators) {219// Configure stderr with all decorators220set_log_config("stderr", "all=off", _all_decorators);221char buf[256];222int ret = jio_snprintf(buf, sizeof(buf), "#1: stderr all=off %s", _all_decorators);223ASSERT_NE(-1, ret);224EXPECT_TRUE(is_described(buf)) << "'" << buf << "' not described after reconfiguration";225226// Now reconfigure logging on stderr with no decorators227set_log_config("stderr", "all=off", "none");228EXPECT_TRUE(is_described("#1: stderr all=off none (reconfigured)\n")) << "Expecting no decorators";229}230231class ConcurrentLogsite : public TestRunnable {232int _id;233234public:235ConcurrentLogsite(int id) : _id(id) {}236void runUnitTest() const override {237log_debug(logging)("ConcurrentLogsite %d emits a log", _id);238}239};240241// Dynamically change decorators while loggings are emitting.242TEST_VM_F(LogConfigurationTest, reconfigure_decorators_MT) {243const int nrOfThreads = 2;244ConcurrentLogsite logsites[nrOfThreads] = {0, 1};245Semaphore done(0);246const long testDurationMillis = 1000;247UnitTestThread* t[nrOfThreads];248249set_log_config(TestLogFileName, "logging=debug", "none", "filecount=0");250set_log_config("stdout", "all=off", "none");251set_log_config("stderr", "all=off", "none");252for (int i = 0; i < nrOfThreads; ++i) {253t[i] = new UnitTestThread(&logsites[i], &done, testDurationMillis);254}255256for (int i = 0; i < nrOfThreads; i++) {257t[i]->doit();258}259260jlong time_start = os::elapsed_counter();261while (true) {262jlong elapsed = (jlong)TimeHelper::counter_to_millis(os::elapsed_counter() - time_start);263if (elapsed > testDurationMillis) {264break;265}266267// Take turn logging with different decorators, either None or All.268set_log_config(TestLogFileName, "logging=debug", "none");269set_log_config(TestLogFileName, "logging=debug", _all_decorators);270}271272for (int i = 0; i < nrOfThreads; ++i) {273done.wait();274}275}276277// Dynamically change tags while loggings are emitting.278TEST_VM_F(LogConfigurationTest, reconfigure_tags_MT) {279const int nrOfThreads = 2;280ConcurrentLogsite logsites[nrOfThreads] = {0, 1};281Semaphore done(0);282const long testDurationMillis = 1000;283UnitTestThread* t[nrOfThreads];284285set_log_config(TestLogFileName, "logging=debug", "", "filecount=0");286set_log_config("stdout", "all=off", "none");287set_log_config("stderr", "all=off", "none");288289for (int i = 0; i < nrOfThreads; ++i) {290t[i] = new UnitTestThread(&logsites[i], &done, testDurationMillis);291}292293for (int i = 0; i < nrOfThreads; i++) {294t[i]->doit();295}296297jlong time_start = os::elapsed_counter();298while (true) {299jlong elapsed = (jlong)TimeHelper::counter_to_millis(os::elapsed_counter() - time_start);300if (elapsed > testDurationMillis) {301break;302}303304// turn on/off the tagset 'logging'.305set_log_config(TestLogFileName, "logging=off");306set_log_config(TestLogFileName, "logging=debug", "", "filecount=0");307// sleep a prime number milliseconds to allow concurrent logsites to write logs308os::naked_short_nanosleep(37);309}310311for (int i = 0; i < nrOfThreads; ++i) {312done.wait();313}314}315316// Test that invalid options cause configuration errors317TEST_VM_F(LogConfigurationTest, invalid_configure_options) {318LogConfiguration::disable_logging();319const char* invalid_outputs[] = { "#2", "invalidtype=123", ":invalid/path}to*file?" };320for (size_t i = 0; i < ARRAY_SIZE(invalid_outputs); i++) {321EXPECT_FALSE(set_log_config(invalid_outputs[i], "", "", "", true))322<< "Accepted invalid output '" << invalid_outputs[i] << "'";323}324EXPECT_FALSE(LogConfiguration::parse_command_line_arguments("all=invalid_level"));325EXPECT_FALSE(LogConfiguration::parse_command_line_arguments("what=invalid"));326EXPECT_FALSE(LogConfiguration::parse_command_line_arguments("all::invalid_decorator"));327EXPECT_FALSE(LogConfiguration::parse_command_line_arguments("*"));328}329330// Test empty configuration options331TEST_VM_F(LogConfigurationTest, parse_empty_command_line_arguments) {332const char* empty_variations[] = { "", ":", "::", ":::", "::::" };333for (size_t i = 0; i < ARRAY_SIZE(empty_variations); i++) {334const char* cmdline = empty_variations[i];335bool ret = LogConfiguration::parse_command_line_arguments(cmdline);336EXPECT_TRUE(ret) << "Error parsing command line arguments '" << cmdline << "'";337for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {338EXPECT_EQ(LogLevel::Unspecified, ts->level_for(&StdoutLog));339}340}341}342343// Test basic command line parsing & configuration344TEST_VM_F(LogConfigurationTest, parse_command_line_arguments) {345// Prepare a command line for logging*=debug on stderr with all decorators346int ret;347char buf[256];348ret = jio_snprintf(buf, sizeof(buf), "logging*=debug:stderr:%s", _all_decorators);349ASSERT_NE(-1, ret);350351bool success = LogConfiguration::parse_command_line_arguments(buf);352EXPECT_TRUE(success) << "Error parsing valid command line arguments '" << buf << "'";353// Ensure the new configuration applied354EXPECT_TRUE(is_described("logging*=debug"));355EXPECT_TRUE(is_described(_all_decorators));356357// Test the configuration of file outputs as well358ret = jio_snprintf(buf, sizeof(buf), ":%s", TestLogFileName);359ASSERT_NE(-1, ret);360EXPECT_TRUE(LogConfiguration::parse_command_line_arguments(buf));361362#ifdef _WINDOWS363// We need to test the special-case parsing for drive letters in364// log file paths e.g. c:\log.txt and c:/log.txt. Our temp directory365// based TestLogFileName should already be the \ format (we print it366// below to visually verify) so we only need to convert to /.367printf("Checked: %s\n", buf);368// First disable logging so the current log file will be closed and we369// can delete it, so that UL won't try to perform log file rotation.370// The rotated file would not be auto-deleted.371set_log_config(TestLogFileName, "all=off");372delete_file(TestLogFileName);373374// now convert \ to /375char* current_pos = strchr(buf,'\\');376while (current_pos != nullptr) {377*current_pos = '/';378current_pos = strchr(current_pos + 1, '\\');379}380printf("Checking: %s\n", buf);381EXPECT_TRUE(LogConfiguration::parse_command_line_arguments(buf));382#endif383384}385386// Test split up log configuration arguments387TEST_VM_F(LogConfigurationTest, parse_log_arguments) {388ResourceMark rm;389stringStream ss;390// Verify that it's possible to configure each individual tag391for (size_t t = 1 /* Skip _NO_TAG */; t < LogTag::Count; t++) {392const LogTagType tag = static_cast<LogTagType>(t);393EXPECT_TRUE(LogConfiguration::parse_log_arguments("stdout", LogTag::name(tag), "", "", &ss));394}395// Same for each level396for (size_t l = 0; l < LogLevel::Count; l++) {397const LogLevelType level = static_cast<LogLevelType>(l);398char expected_buf[256];399int ret = jio_snprintf(expected_buf, sizeof(expected_buf), "all=%s", LogLevel::name(level));400ASSERT_NE(-1, ret);401EXPECT_TRUE(LogConfiguration::parse_log_arguments("stderr", expected_buf, "", "", &ss));402}403// And for each decorator404for (size_t d = 0; d < LogDecorators::Count; d++) {405const LogDecorators::Decorator decorator = static_cast<LogDecorators::Decorator>(d);406EXPECT_TRUE(LogConfiguration::parse_log_arguments("#0", "", LogDecorators::name(decorator), "", &ss));407}408}409410TEST_VM_F(LogConfigurationTest, configure_stdout) {411// Start out with all logging disabled412LogConfiguration::disable_logging();413414// Enable 'logging=info', verifying it has been set415LogConfiguration::configure_stdout(LogLevel::Info, true, LOG_TAGS(logging));416EXPECT_TRUE(log_is_enabled(Info, logging));417EXPECT_FALSE(log_is_enabled(Debug, logging));418EXPECT_FALSE(log_is_enabled(Info, gc));419LogTagSet* logging_ts = &LogTagSetMapping<LOG_TAGS(logging)>::tagset();420EXPECT_EQ(LogLevel::Info, logging_ts->level_for(&StdoutLog));421422// Enable 'gc=debug' (no wildcard), verifying no other tags are enabled423LogConfiguration::configure_stdout(LogLevel::Debug, true, LOG_TAGS(gc));424EXPECT_TRUE(log_is_enabled(Debug, gc));425EXPECT_TRUE(log_is_enabled(Info, logging));426EXPECT_FALSE(log_is_enabled(Debug, gc, heap));427for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {428if (ts->contains(PREFIX_LOG_TAG(gc))) {429if (ts->ntags() == 1) {430EXPECT_EQ(LogLevel::Debug, ts->level_for(&StdoutLog));431} else {432EXPECT_EQ(LogLevel::Off, ts->level_for(&StdoutLog));433}434}435}436437// Enable 'gc*=trace' (with wildcard), verifying that all tag combinations with gc are enabled (gc+...)438LogConfiguration::configure_stdout(LogLevel::Trace, false, LOG_TAGS(gc));439EXPECT_TRUE(log_is_enabled(Trace, gc));440EXPECT_TRUE(log_is_enabled(Trace, gc, heap));441for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {442if (ts->contains(PREFIX_LOG_TAG(gc))) {443EXPECT_EQ(LogLevel::Trace, ts->level_for(&StdoutLog));444} else if (ts == logging_ts) {445// Previous setting for 'logging' should remain446EXPECT_EQ(LogLevel::Info, ts->level_for(&StdoutLog));447} else {448EXPECT_EQ(LogLevel::Off, ts->level_for(&StdoutLog));449}450}451452// Disable 'gc*' and 'logging', verifying all logging is properly disabled453LogConfiguration::configure_stdout(LogLevel::Off, true, LOG_TAGS(logging));454EXPECT_FALSE(log_is_enabled(Error, logging));455LogConfiguration::configure_stdout(LogLevel::Off, false, LOG_TAGS(gc));456EXPECT_FALSE(log_is_enabled(Error, gc));457EXPECT_FALSE(log_is_enabled(Error, gc, heap));458for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {459EXPECT_EQ(LogLevel::Off, ts->level_for(&StdoutLog));460}461}462463static int Test_logconfiguration_subscribe_triggered = 0;464static void Test_logconfiguration_subscribe_helper() {465Test_logconfiguration_subscribe_triggered++;466}467468TEST_VM_F(LogConfigurationTest, subscribe) {469ResourceMark rm;470Log(logging) log;471set_log_config("stdout", "logging*=trace");472473LogConfiguration::register_update_listener(&Test_logconfiguration_subscribe_helper);474475LogStream ls(log.error());476LogConfiguration::parse_log_arguments("stdout", "logging=trace", NULL, NULL, &ls);477ASSERT_EQ(1, Test_logconfiguration_subscribe_triggered);478479LogConfiguration::configure_stdout(LogLevel::Debug, true, LOG_TAGS(gc));480ASSERT_EQ(2, Test_logconfiguration_subscribe_triggered);481482LogConfiguration::disable_logging();483ASSERT_EQ(3, Test_logconfiguration_subscribe_triggered);484}485486TEST_VM_F(LogConfigurationTest, parse_invalid_tagset) {487static const char* invalid_tagset = "logging+start+exit+safepoint+gc"; // Must not exist for test to function.488489// Make sure warning is produced if one or more configured tagsets are invalid490ResourceMark rm;491stringStream ss;492bool success = LogConfiguration::parse_log_arguments("stdout", invalid_tagset, NULL, NULL, &ss);493const char* msg = ss.as_string();494EXPECT_TRUE(success) << "Should only cause a warning, not an error";495EXPECT_TRUE(string_contains_substring(msg, "No tag set matches selection:"));496EXPECT_TRUE(string_contains_substring(msg, invalid_tagset));497}498499TEST_VM_F(LogConfigurationTest, output_name_normalization) {500const char* patterns[] = { "%s", "file=%s", "\"%s\"", "file=\"%s\"" };501char buf[1 * K];502for (size_t i = 0; i < ARRAY_SIZE(patterns); i++) {503int ret = jio_snprintf(buf, sizeof(buf), patterns[i], TestLogFileName);504ASSERT_NE(-1, ret);505set_log_config(buf, "logging=trace");506EXPECT_TRUE(is_described("#2: "));507EXPECT_TRUE(is_described(TestLogFileName));508EXPECT_FALSE(is_described("#3: "))509<< "duplicate file output due to incorrect normalization for pattern: " << patterns[i];510}511512// Make sure prefixes are ignored when used within quotes513// (this should create a log with "file=" in its filename)514// Note that the filename cannot contain directories because515// it is being prefixed with "file=".516const char* leafFileName = "\"file=leaf_file_name\"";517set_log_config(leafFileName, "logging=trace");518EXPECT_TRUE(is_described("#3: ")) << "prefix within quotes not ignored as it should be";519set_log_config(leafFileName, "all=off");520521// Remove the extra log file created522delete_file("file=leaf_file_name");523}524525static size_t count_occurrences(const char* haystack, const char* needle) {526size_t count = 0;527for (const char* p = strstr(haystack, needle); p != NULL; p = strstr(p + 1, needle)) {528count++;529}530return count;531}532533TEST_OTHER_VM(LogConfiguration, output_reconfigured) {534ResourceMark rm;535stringStream ss;536537EXPECT_FALSE(is_described("(reconfigured)"));538539bool success = LogConfiguration::parse_log_arguments("#1", "all=warning", NULL, NULL, &ss);540ASSERT_TRUE(success);541EXPECT_EQ(0u, ss.size());542543LogConfiguration::describe(&ss);544EXPECT_EQ(1u, count_occurrences(ss.as_string(), "(reconfigured)"));545546ss.reset();547LogConfiguration::configure_stdout(LogLevel::Info, false, LOG_TAGS(logging));548LogConfiguration::describe(&ss);549EXPECT_EQ(2u, count_occurrences(ss.as_string(), "(reconfigured)"));550}551552TEST_VM_F(LogConfigurationTest, suggest_similar_selection) {553static const char* nonexisting_tagset = "logging+start+exit+safepoint+gc";554555ResourceMark rm;556stringStream ss;557LogConfiguration::parse_log_arguments("stdout", nonexisting_tagset, NULL, NULL, &ss);558559const char* suggestion = ss.as_string();560SCOPED_TRACE(suggestion);561EXPECT_TRUE(string_contains_substring(ss.as_string(), "Did you mean any of the following?"));562EXPECT_TRUE(string_contains_substring(suggestion, "logging") ||563string_contains_substring(suggestion, "start") ||564string_contains_substring(suggestion, "exit") ||565string_contains_substring(suggestion, "safepoint") ||566string_contains_substring(suggestion, "gc")) <<567"suggestion must contain AT LEAST one of the tags in user supplied selection";568}569570571