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