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