1/*
2 * Copyright (c) 2015, 2019, 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 "logging/log.hpp"
27#include "logging/logConfiguration.hpp"
28#include "logging/logDecorations.hpp"
29#include "logging/logDecorators.hpp"
30#include "logging/logDiagnosticCommand.hpp"
31#include "logging/logFileOutput.hpp"
32#include "logging/logOutput.hpp"
33#include "logging/logSelectionList.hpp"
34#include "logging/logStream.hpp"
35#include "logging/logTagSet.hpp"
36#include "memory/allocation.inline.hpp"
37#include "memory/resourceArea.hpp"
38#include "runtime/os.inline.hpp"
39#include "runtime/semaphore.hpp"
40#include "utilities/globalDefinitions.hpp"
41
42LogOutput** LogConfiguration::_outputs = NULL;
43size_t LogConfiguration::_n_outputs = 0;
44
45LogConfiguration::UpdateListenerFunction* LogConfiguration::_listener_callbacks = NULL;
46size_t LogConfiguration::_n_listener_callbacks = 0;
47
48// LogFileOutput is the default type of output, its type prefix should be used if no type was specified
49static const char* implicit_output_prefix = LogFileOutput::Prefix;
50
51// Stack object to take the lock for configuring the logging.
52// Should only be held during the critical parts of the configuration
53// (when calling configure_output or reading/modifying the outputs array).
54// Thread must never block when holding this lock.
55class ConfigurationLock : public StackObj {
56 private:
57 // Semaphore used as lock
58 static Semaphore _semaphore;
59 debug_only(static intx _locking_thread_id;)
60 public:
61 ConfigurationLock() {
62 _semaphore.wait();
63 debug_only(_locking_thread_id = os::current_thread_id());
64 }
65 ~ConfigurationLock() {
66 debug_only(_locking_thread_id = -1);
67 _semaphore.signal();
68 }
69 debug_only(static bool current_thread_has_lock();)
70};
71
72Semaphore ConfigurationLock::_semaphore(1);
73#ifdef ASSERT
74intx ConfigurationLock::_locking_thread_id = -1;
75bool ConfigurationLock::current_thread_has_lock() {
76 return _locking_thread_id == os::current_thread_id();
77}
78#endif
79
80void LogConfiguration::post_initialize() {
81 // Reset the reconfigured status of all outputs
82 for (size_t i = 0; i < _n_outputs; i++) {
83 _outputs[i]->_reconfigured = false;
84 }
85
86 LogDiagnosticCommand::registerCommand();
87 Log(logging) log;
88 if (log.is_info()) {
89 log.info("Log configuration fully initialized.");
90 log_develop_info(logging)("Develop logging is available.");
91
92 LogStream info_stream(log.info());
93 describe_available(&info_stream);
94
95 LogStream debug_stream(log.debug());
96 LogTagSet::list_all_tagsets(&debug_stream);
97
98 ConfigurationLock cl;
99 describe_current_configuration(&info_stream);
100 }
101}
102
103void LogConfiguration::initialize(jlong vm_start_time) {
104 LogFileOutput::set_file_name_parameters(vm_start_time);
105 LogDecorations::initialize(vm_start_time);
106 assert(_outputs == NULL, "Should not initialize _outputs before this function, initialize called twice?");
107 _outputs = NEW_C_HEAP_ARRAY(LogOutput*, 2, mtLogging);
108 _outputs[0] = &StdoutLog;
109 _outputs[1] = &StderrLog;
110 _n_outputs = 2;
111}
112
113void LogConfiguration::finalize() {
114 for (size_t i = _n_outputs; i > 0; i--) {
115 disable_output(i - 1);
116 }
117 FREE_C_HEAP_ARRAY(LogOutput*, _outputs);
118}
119
120// Normalizes the given LogOutput name to type=name form.
121// For example, foo, "foo", file="foo", will all be normalized to file=foo (no quotes, prefixed).
122static bool normalize_output_name(const char* full_name, char* buffer, size_t len, outputStream* errstream) {
123 const char* start_quote = strchr(full_name, '"');
124 const char* equals = strchr(full_name, '=');
125 const bool quoted = start_quote != NULL;
126 const bool is_stdout_or_stderr = (strcmp(full_name, "stdout") == 0 || strcmp(full_name, "stderr") == 0);
127
128 // ignore equals sign within quotes
129 if (quoted && equals > start_quote) {
130 equals = NULL;
131 }
132
133 const char* prefix = "";
134 size_t prefix_len = 0;
135 const char* name = full_name;
136 if (equals != NULL) {
137 // split on equals sign
138 name = equals + 1;
139 prefix = full_name;
140 prefix_len = equals - full_name + 1;
141 } else if (!is_stdout_or_stderr) {
142 prefix = implicit_output_prefix;
143 prefix_len = strlen(prefix);
144 }
145 size_t name_len = strlen(name);
146
147 if (quoted) {
148 const char* end_quote = strchr(start_quote + 1, '"');
149 if (end_quote == NULL) {
150 errstream->print_cr("Output name has opening quote but is missing a terminating quote.");
151 return false;
152 }
153 if (start_quote != name || end_quote[1] != '\0') {
154 errstream->print_cr("Output name can not be partially quoted."
155 " Either surround the whole name with quotation marks,"
156 " or do not use quotation marks at all.");
157 return false;
158 }
159 // strip start and end quote
160 name++;
161 name_len -= 2;
162 }
163
164 int ret = jio_snprintf(buffer, len, "%.*s%.*s", prefix_len, prefix, name_len, name);
165 assert(ret > 0, "buffer issue");
166 return true;
167}
168
169size_t LogConfiguration::find_output(const char* name) {
170 for (size_t i = 0; i < _n_outputs; i++) {
171 if (strcmp(_outputs[i]->name(), name) == 0) {
172 return i;
173 }
174 }
175 return SIZE_MAX;
176}
177
178LogOutput* LogConfiguration::new_output(const char* name,
179 const char* options,
180 outputStream* errstream) {
181 LogOutput* output;
182 if (strncmp(name, LogFileOutput::Prefix, strlen(LogFileOutput::Prefix)) == 0) {
183 output = new LogFileOutput(name);
184 } else {
185 errstream->print_cr("Unsupported log output type: %s", name);
186 return NULL;
187 }
188
189 bool success = output->initialize(options, errstream);
190 if (!success) {
191 errstream->print_cr("Initialization of output '%s' using options '%s' failed.", name, options);
192 delete output;
193 return NULL;
194 }
195 return output;
196}
197
198size_t LogConfiguration::add_output(LogOutput* output) {
199 size_t idx = _n_outputs++;
200 _outputs = REALLOC_C_HEAP_ARRAY(LogOutput*, _outputs, _n_outputs, mtLogging);
201 _outputs[idx] = output;
202 return idx;
203}
204
205void LogConfiguration::delete_output(size_t idx) {
206 assert(idx > 1 && idx < _n_outputs,
207 "idx must be in range 1 < idx < _n_outputs, but idx = " SIZE_FORMAT
208 " and _n_outputs = " SIZE_FORMAT, idx, _n_outputs);
209 LogOutput* output = _outputs[idx];
210 // Swap places with the last output and shrink the array
211 _outputs[idx] = _outputs[--_n_outputs];
212 _outputs = REALLOC_C_HEAP_ARRAY(LogOutput*, _outputs, _n_outputs, mtLogging);
213 delete output;
214}
215
216void LogConfiguration::configure_output(size_t idx, const LogSelectionList& selections, const LogDecorators& decorators) {
217 assert(ConfigurationLock::current_thread_has_lock(), "Must hold configuration lock to call this function.");
218 assert(idx < _n_outputs, "Invalid index, idx = " SIZE_FORMAT " and _n_outputs = " SIZE_FORMAT, idx, _n_outputs);
219 LogOutput* output = _outputs[idx];
220
221 output->_reconfigured = true;
222
223 size_t on_level[LogLevel::Count] = {0};
224
225 bool enabled = false;
226 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
227 LogLevelType level = selections.level_for(*ts);
228
229 // Ignore tagsets that do not, and will not log on the output
230 if (!ts->has_output(output) && (level == LogLevel::NotMentioned || level == LogLevel::Off)) {
231 on_level[LogLevel::Off]++;
232 continue;
233 }
234
235 // Update decorators before adding/updating output level,
236 // so that the tagset will have the necessary decorators when requiring them.
237 if (level != LogLevel::Off) {
238 ts->update_decorators(decorators);
239 }
240
241 // Set the new level, if it changed
242 if (level != LogLevel::NotMentioned) {
243 ts->set_output_level(output, level);
244 } else {
245 // Look up the previously set level for this output on this tagset
246 level = ts->level_for(output);
247 }
248
249 if (level != LogLevel::Off) {
250 // Keep track of whether or not the output is ever used by some tagset
251 enabled = true;
252 }
253
254 // Track of the number of tag sets on each level
255 on_level[level]++;
256 }
257
258 // It is now safe to set the new decorators for the actual output
259 output->set_decorators(decorators);
260
261 // Update the decorators on all tagsets to get rid of unused decorators
262 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
263 ts->update_decorators();
264 }
265
266 if (!enabled && idx > 1) {
267 // Output is unused and should be removed, unless it is stdout/stderr (idx < 2)
268 delete_output(idx);
269 return;
270 }
271
272 output->update_config_string(on_level);
273 assert(strlen(output->config_string()) > 0, "should always have a config description");
274}
275
276void LogConfiguration::disable_output(size_t idx) {
277 assert(idx < _n_outputs, "invalid index: " SIZE_FORMAT " (_n_outputs: " SIZE_FORMAT ")", idx, _n_outputs);
278 LogOutput* out = _outputs[idx];
279
280 // Remove the output from all tagsets.
281 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
282 ts->set_output_level(out, LogLevel::Off);
283 ts->update_decorators();
284 }
285
286 // Delete the output unless stdout or stderr (idx 0 or 1)
287 if (idx > 1) {
288 delete_output(idx);
289 } else {
290 out->set_config_string("all=off");
291 }
292}
293
294void LogConfiguration::disable_logging() {
295 ConfigurationLock cl;
296 for (size_t i = _n_outputs; i > 0; i--) {
297 disable_output(i - 1);
298 }
299 notify_update_listeners();
300}
301
302void LogConfiguration::configure_stdout(LogLevelType level, int exact_match, ...) {
303 size_t i;
304 va_list ap;
305 LogTagType tags[LogTag::MaxTags];
306 va_start(ap, exact_match);
307 for (i = 0; i < LogTag::MaxTags; i++) {
308 LogTagType tag = static_cast<LogTagType>(va_arg(ap, int));
309 tags[i] = tag;
310 if (tag == LogTag::__NO_TAG) {
311 assert(i > 0, "Must specify at least one tag!");
312 break;
313 }
314 }
315 assert(i < LogTag::MaxTags || static_cast<LogTagType>(va_arg(ap, int)) == LogTag::__NO_TAG,
316 "Too many tags specified! Can only have up to " SIZE_FORMAT " tags in a tag set.", LogTag::MaxTags);
317 va_end(ap);
318
319 LogSelection selection(tags, !exact_match, level);
320 assert(selection.tag_sets_selected() > 0,
321 "configure_stdout() called with invalid/non-existing log selection");
322 LogSelectionList list(selection);
323
324 // Apply configuration to stdout (output #0), with the same decorators as before.
325 ConfigurationLock cl;
326 configure_output(0, list, _outputs[0]->decorators());
327 notify_update_listeners();
328}
329
330bool LogConfiguration::parse_command_line_arguments(const char* opts) {
331 char* copy = os::strdup_check_oom(opts, mtLogging);
332
333 // Split the option string to its colon separated components.
334 char* str = copy;
335 char* substrings[4] = {0};
336 for (int i = 0 ; i < 4; i++) {
337 substrings[i] = str;
338
339 // Find the next colon or quote
340 char* next = strpbrk(str, ":\"");
341#ifdef _WINDOWS
342 // Skip over Windows paths such as "C:\..."
343 // Handle both C:\... and file=C:\..."
344 if (next != NULL && next[0] == ':' && next[1] == '\\') {
345 if (next == str + 1 || (strncmp(str, "file=", 5) == 0)) {
346 next = strpbrk(next + 1, ":\"");
347 }
348 }
349#endif
350 while (next != NULL && *next == '"') {
351 char* end_quote = strchr(next + 1, '"');
352 if (end_quote == NULL) {
353 log_error(logging)("Missing terminating quote in -Xlog option '%s'", str);
354 os::free(copy);
355 return false;
356 }
357 // Keep searching after the quoted substring
358 next = strpbrk(end_quote + 1, ":\"");
359 }
360
361 if (next != NULL) {
362 *next = '\0';
363 str = next + 1;
364 } else {
365 break;
366 }
367 }
368
369 // Parse and apply the separated configuration options
370 char* what = substrings[0];
371 char* output = substrings[1];
372 char* decorators = substrings[2];
373 char* output_options = substrings[3];
374 char errbuf[512];
375 stringStream ss(errbuf, sizeof(errbuf));
376 bool success = parse_log_arguments(output, what, decorators, output_options, &ss);
377
378 if (ss.size() > 0) {
379 // If it failed, log the error. If it didn't fail, but something was written
380 // to the stream, log it as a warning.
381 LogLevelType level = success ? LogLevel::Warning : LogLevel::Error;
382
383 Log(logging) log;
384 char* start = errbuf;
385 char* end = strchr(start, '\n');
386 assert(end != NULL, "line must end with newline '%s'", start);
387 do {
388 assert(start < errbuf + sizeof(errbuf) &&
389 end < errbuf + sizeof(errbuf),
390 "buffer overflow");
391 *end = '\0';
392 log.write(level, "%s", start);
393 start = end + 1;
394 end = strchr(start, '\n');
395 assert(end != NULL || *start == '\0', "line must end with newline '%s'", start);
396 } while (end != NULL);
397 }
398
399 os::free(copy);
400 return success;
401}
402
403bool LogConfiguration::parse_log_arguments(const char* outputstr,
404 const char* selectionstr,
405 const char* decoratorstr,
406 const char* output_options,
407 outputStream* errstream) {
408 assert(errstream != NULL, "errstream can not be NULL");
409 if (outputstr == NULL || strlen(outputstr) == 0) {
410 outputstr = "stdout";
411 }
412
413 LogSelectionList selections;
414 if (!selections.parse(selectionstr, errstream)) {
415 return false;
416 }
417
418 LogDecorators decorators;
419 if (!decorators.parse(decoratorstr, errstream)) {
420 return false;
421 }
422
423 ConfigurationLock cl;
424 size_t idx;
425 if (outputstr[0] == '#') { // Output specified using index
426 int ret = sscanf(outputstr + 1, SIZE_FORMAT, &idx);
427 if (ret != 1 || idx >= _n_outputs) {
428 errstream->print_cr("Invalid output index '%s'", outputstr);
429 return false;
430 }
431 } else { // Output specified using name
432 // Normalize the name, stripping quotes and ensures it includes type prefix
433 size_t len = strlen(outputstr) + strlen(implicit_output_prefix) + 1;
434 char* normalized = NEW_C_HEAP_ARRAY(char, len, mtLogging);
435 if (!normalize_output_name(outputstr, normalized, len, errstream)) {
436 return false;
437 }
438
439 idx = find_output(normalized);
440 if (idx == SIZE_MAX) {
441 // Attempt to create and add the output
442 LogOutput* output = new_output(normalized, output_options, errstream);
443 if (output != NULL) {
444 idx = add_output(output);
445 }
446 } else if (output_options != NULL && strlen(output_options) > 0) {
447 errstream->print_cr("Output options for existing outputs are ignored.");
448 }
449
450 FREE_C_HEAP_ARRAY(char, normalized);
451 if (idx == SIZE_MAX) {
452 return false;
453 }
454 }
455 configure_output(idx, selections, decorators);
456 notify_update_listeners();
457 selections.verify_selections(errstream);
458 return true;
459}
460
461void LogConfiguration::describe_available(outputStream* out) {
462 out->print("Available log levels:");
463 for (size_t i = 0; i < LogLevel::Count; i++) {
464 out->print("%s %s", (i == 0 ? "" : ","), LogLevel::name(static_cast<LogLevelType>(i)));
465 }
466 out->cr();
467
468 out->print("Available log decorators:");
469 for (size_t i = 0; i < LogDecorators::Count; i++) {
470 LogDecorators::Decorator d = static_cast<LogDecorators::Decorator>(i);
471 out->print("%s %s (%s)", (i == 0 ? "" : ","), LogDecorators::name(d), LogDecorators::abbreviation(d));
472 }
473 out->cr();
474
475 out->print("Available log tags:");
476 LogTag::list_tags(out);
477
478 LogTagSet::describe_tagsets(out);
479}
480
481void LogConfiguration::describe_current_configuration(outputStream* out) {
482 out->print_cr("Log output configuration:");
483 for (size_t i = 0; i < _n_outputs; i++) {
484 out->print(" #" SIZE_FORMAT ": ", i);
485 _outputs[i]->describe(out);
486 if (_outputs[i]->is_reconfigured()) {
487 out->print(" (reconfigured)");
488 }
489 out->cr();
490 }
491}
492
493void LogConfiguration::describe(outputStream* out) {
494 describe_available(out);
495 ConfigurationLock cl;
496 describe_current_configuration(out);
497}
498
499void LogConfiguration::print_command_line_help(outputStream* out) {
500 out->print_cr("-Xlog Usage: -Xlog[:[selections][:[output][:[decorators][:output-options]]]]");
501 out->print_cr("\t where 'selections' are combinations of tags and levels of the form tag1[+tag2...][*][=level][,...]");
502 out->print_cr("\t NOTE: Unless wildcard (*) is specified, only log messages tagged with exactly the tags specified will be matched.");
503 out->cr();
504
505 out->print_cr("Available log levels:");
506 for (size_t i = 0; i < LogLevel::Count; i++) {
507 out->print("%s %s", (i == 0 ? "" : ","), LogLevel::name(static_cast<LogLevelType>(i)));
508 }
509 out->cr();
510 out->cr();
511
512 out->print_cr("Available log decorators: ");
513 for (size_t i = 0; i < LogDecorators::Count; i++) {
514 LogDecorators::Decorator d = static_cast<LogDecorators::Decorator>(i);
515 out->print("%s %s (%s)", (i == 0 ? "" : ","), LogDecorators::name(d), LogDecorators::abbreviation(d));
516 }
517 out->cr();
518 out->print_cr(" Decorators can also be specified as 'none' for no decoration.");
519 out->cr();
520
521 out->print_cr("Available log tags:");
522 LogTag::list_tags(out);
523 out->print_cr(" Specifying 'all' instead of a tag combination matches all tag combinations.");
524 out->cr();
525
526 LogTagSet::describe_tagsets(out);
527
528 out->print_cr("\nAvailable log outputs:");
529 out->print_cr(" stdout/stderr");
530 out->print_cr(" file=<filename>");
531 out->print_cr(" If the filename contains %%p and/or %%t, they will expand to the JVM's PID and startup timestamp, respectively.");
532 out->print_cr(" Additional output-options for file outputs:");
533 out->print_cr(" filesize=.. - Target byte size for log rotation (supports K/M/G suffix)."
534 " If set to 0, log rotation will not trigger automatically,"
535 " but can be performed manually (see the VM.log DCMD).");
536 out->print_cr(" filecount=.. - Number of files to keep in rotation (not counting the active file)."
537 " If set to 0, log rotation is disabled."
538 " This will cause existing log files to be overwritten.");
539 out->cr();
540
541 out->print_cr("Some examples:");
542 out->print_cr(" -Xlog");
543 out->print_cr("\t Log all messages up to 'info' level to stdout with 'uptime', 'levels' and 'tags' decorations.");
544 out->print_cr("\t (Equivalent to -Xlog:all=info:stdout:uptime,levels,tags).");
545 out->cr();
546
547 out->print_cr(" -Xlog:gc");
548 out->print_cr("\t Log messages tagged with 'gc' tag up to 'info' level to stdout, with default decorations.");
549 out->cr();
550
551 out->print_cr(" -Xlog:gc,safepoint");
552 out->print_cr("\t Log messages tagged either with 'gc' or 'safepoint' tags, both up to 'info' level, to stdout, with default decorations.");
553 out->print_cr("\t (Messages tagged with both 'gc' and 'safepoint' will not be logged.)");
554 out->cr();
555
556 out->print_cr(" -Xlog:gc+ref=debug");
557 out->print_cr("\t Log messages tagged with both 'gc' and 'ref' tags, up to 'debug' level, to stdout, with default decorations.");
558 out->print_cr("\t (Messages tagged only with one of the two tags will not be logged.)");
559 out->cr();
560
561 out->print_cr(" -Xlog:gc=debug:file=gc.txt:none");
562 out->print_cr("\t Log messages tagged with 'gc' tag up to 'debug' level to file 'gc.txt' with no decorations.");
563 out->cr();
564
565 out->print_cr(" -Xlog:gc=trace:file=gctrace.txt:uptimemillis,pid:filecount=5,filesize=1m");
566 out->print_cr("\t Log messages tagged with 'gc' tag up to 'trace' level to a rotating fileset of 5 files of size 1MB,");
567 out->print_cr("\t using the base name 'gctrace.txt', with 'uptimemillis' and 'pid' decorations.");
568 out->cr();
569
570 out->print_cr(" -Xlog:gc::uptime,tid");
571 out->print_cr("\t Log messages tagged with 'gc' tag up to 'info' level to output 'stdout', using 'uptime' and 'tid' decorations.");
572 out->cr();
573
574 out->print_cr(" -Xlog:gc*=info,safepoint*=off");
575 out->print_cr("\t Log messages tagged with at least 'gc' up to 'info' level, but turn off logging of messages tagged with 'safepoint'.");
576 out->print_cr("\t (Messages tagged with both 'gc' and 'safepoint' will not be logged.)");
577 out->cr();
578
579 out->print_cr(" -Xlog:disable -Xlog:safepoint=trace:safepointtrace.txt");
580 out->print_cr("\t Turn off all logging, including warnings and errors,");
581 out->print_cr("\t and then enable messages tagged with 'safepoint' up to 'trace' level to file 'safepointtrace.txt'.");
582}
583
584void LogConfiguration::rotate_all_outputs() {
585 // Start from index 2 since neither stdout nor stderr can be rotated.
586 for (size_t idx = 2; idx < _n_outputs; idx++) {
587 _outputs[idx]->force_rotate();
588 }
589}
590
591void LogConfiguration::register_update_listener(UpdateListenerFunction cb) {
592 assert(cb != NULL, "Should not register NULL as listener");
593 ConfigurationLock cl;
594 size_t idx = _n_listener_callbacks++;
595 _listener_callbacks = REALLOC_C_HEAP_ARRAY(UpdateListenerFunction,
596 _listener_callbacks,
597 _n_listener_callbacks,
598 mtLogging);
599 _listener_callbacks[idx] = cb;
600}
601
602void LogConfiguration::notify_update_listeners() {
603 assert(ConfigurationLock::current_thread_has_lock(), "notify_update_listeners must be called in ConfigurationLock scope (lock held)");
604 for (size_t i = 0; i < _n_listener_callbacks; i++) {
605 _listener_callbacks[i]();
606 }
607}
608