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
38class LogConfigurationTest : public LogTestFixture {
39 protected:
40  static char _all_decorators[256];
41
42 public:
43  static void SetUpTestCase();
44};
45
46char LogConfigurationTest::_all_decorators[256];
47
48// Prepare _all_decorators to contain the full list of decorators (comma separated)
49void 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()
59static 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
66TEST_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
120TEST_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
149TEST_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
165TEST_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
190TEST_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
218TEST_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
232TEST_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
245TEST_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
258TEST_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
278TEST_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
301TEST_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
354static int Test_logconfiguration_subscribe_triggered = 0;
355static void Test_logconfiguration_subscribe_helper() {
356  Test_logconfiguration_subscribe_triggered++;
357}
358
359TEST_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
377TEST_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
390TEST_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}
416