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