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] = &StdoutLog; 102 _outputs[1] = &StderrLog; 103 _n_outputs = 2; 104 } 105 106 void LogConfiguration::finalize() { 107 for (size_t i = _n_outputs; i > 0; i--) { 108 disable_output(i - 1); 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 assert(idx < _n_outputs, "invalid index: " SIZE_FORMAT " (_n_outputs: " SIZE_FORMAT ")", idx, _n_outputs); 274 LogOutput* out = _outputs[idx]; 275 276 // Remove the output from all tagsets. 277 for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) { 278 ts->set_output_level(out, LogLevel::Off); 279 ts->update_decorators(); 280 } 281 282 // Delete the output unless stdout or stderr (idx 0 or 1) 283 if (idx > 1) { 284 delete_output(idx); 285 } else { 286 out->set_config_string("all=off"); 287 } 288 } 289 290 void LogConfiguration::disable_logging() { 291 ConfigurationLock cl; 292 for (size_t i = _n_outputs; i > 0; i--) { 293 disable_output(i - 1); 294 } 295 notify_update_listeners(); 296 } 297 298 void LogConfiguration::configure_stdout(LogLevelType level, bool exact_match, ...) { 299 size_t i; 300 va_list ap; 301 LogTagLevelExpression expr; 302 va_start(ap, exact_match); 303 for (i = 0; i < LogTag::MaxTags; i++) { 304 LogTagType tag = static_cast<LogTagType>(va_arg(ap, int)); 305 expr.add_tag(tag); 306 if (tag == LogTag::__NO_TAG) { 307 assert(i > 0, "Must specify at least one tag!"); 308 break; 309 } 310 } 311 assert(i < LogTag::MaxTags || static_cast<LogTagType>(va_arg(ap, int)) == LogTag::__NO_TAG, 312 "Too many tags specified! Can only have up to " SIZE_FORMAT " tags in a tag set.", LogTag::MaxTags); 313 va_end(ap); 314 315 if (!exact_match) { 316 expr.set_allow_other_tags(); 317 } 318 expr.set_level(level); 319 expr.new_combination(); 320 assert(expr.verify_tagsets(), 321 "configure_stdout() called with invalid/non-existing tag set"); 322 323 // Apply configuration to stdout (output #0), with the same decorators as before. 324 ConfigurationLock cl; 325 configure_output(0, expr, _outputs[0]->decorators()); 326 notify_update_listeners(); 327 } 328 329 bool LogConfiguration::parse_command_line_arguments(const char* opts) { 330 char* copy = os::strdup_check_oom(opts, mtLogging); 331 332 // Split the option string to its colon separated components. 333 char* str = copy; 334 char* substrings[4] = {0}; 335 for (int i = 0 ; i < 4; i++) { 336 substrings[i] = str; 337 338 // Find the next colon or quote 339 char* next = strpbrk(str, ":\""); 340 while (next != NULL && *next == '"') { 341 char* end_quote = strchr(next + 1, '"'); 342 if (end_quote == NULL) { 343 log_error(logging)("Missing terminating quote in -Xlog option '%s'", str); 344 os::free(copy); 345 return false; 346 } 347 // Keep searching after the quoted substring 348 next = strpbrk(end_quote + 1, ":\""); 349 } 350 351 if (next != NULL) { 352 *next = '\0'; 353 str = next + 1; 354 } else { 355 break; 356 } 357 } 358 359 // Parse and apply the separated configuration options 360 char* what = substrings[0]; 361 char* output = substrings[1]; 362 char* decorators = substrings[2]; 363 char* output_options = substrings[3]; 364 char errbuf[512]; 365 stringStream ss(errbuf, sizeof(errbuf)); 366 bool success = parse_log_arguments(output, what, decorators, output_options, &ss); 367 368 if (ss.size() > 0) { 369 errbuf[strlen(errbuf) - 1] = '\0'; // Strip trailing newline 370 // If it failed, log the error. If it didn't fail, but something was written 371 // to the stream, log it as a warning. 372 if (!success) { 373 log_error(logging)("%s", ss.base()); 374 } else { 375 log_warning(logging)("%s", ss.base()); 376 } 377 } 378 379 os::free(copy); 380 return success; 381 } 382 383 bool LogConfiguration::parse_log_arguments(const char* outputstr, 384 const char* what, 385 const char* decoratorstr, 386 const char* output_options, 387 outputStream* errstream) { 388 assert(errstream != NULL, "errstream can not be NULL"); 389 if (outputstr == NULL || strlen(outputstr) == 0) { 390 outputstr = "stdout"; 391 } 392 393 LogTagLevelExpression expr; 394 if (!expr.parse(what, errstream)) { 395 return false; 396 } 397 398 LogDecorators decorators; 399 if (!decorators.parse(decoratorstr, errstream)) { 400 return false; 401 } 402 403 ConfigurationLock cl; 404 size_t idx; 405 if (outputstr[0] == '#') { // Output specified using index 406 int ret = sscanf(outputstr + 1, SIZE_FORMAT, &idx); 407 if (ret != 1 || idx >= _n_outputs) { 408 errstream->print_cr("Invalid output index '%s'", outputstr); 409 return false; 410 } 411 } else { // Output specified using name 412 // Normalize the name, stripping quotes and ensures it includes type prefix 413 size_t len = strlen(outputstr) + strlen(implicit_output_prefix) + 1; 414 char* normalized = NEW_C_HEAP_ARRAY(char, len, mtLogging); 415 if (!normalize_output_name(outputstr, normalized, len, errstream)) { 416 return false; 417 } 418 419 idx = find_output(normalized); 420 if (idx == SIZE_MAX) { 421 // Attempt to create and add the output 422 LogOutput* output = new_output(normalized, output_options, errstream); 423 if (output != NULL) { 424 idx = add_output(output); 425 } 426 } else if (output_options != NULL && strlen(output_options) > 0) { 427 errstream->print_cr("Output options for existing outputs are ignored."); 428 } 429 430 FREE_C_HEAP_ARRAY(char, normalized); 431 if (idx == SIZE_MAX) { 432 return false; 433 } 434 } 435 configure_output(idx, expr, decorators); 436 notify_update_listeners(); 437 expr.verify_tagsets(errstream); 438 return true; 439 } 440 441 void LogConfiguration::describe_available(outputStream* out){ 442 out->print("Available log levels:"); 443 for (size_t i = 0; i < LogLevel::Count; i++) { 444 out->print("%s %s", (i == 0 ? "" : ","), LogLevel::name(static_cast<LogLevelType>(i))); 445 } 446 out->cr(); 447 448 out->print("Available log decorators:"); 449 for (size_t i = 0; i < LogDecorators::Count; i++) { 450 LogDecorators::Decorator d = static_cast<LogDecorators::Decorator>(i); 451 out->print("%s %s (%s)", (i == 0 ? "" : ","), LogDecorators::name(d), LogDecorators::abbreviation(d)); 452 } 453 out->cr(); 454 455 out->print("Available log tags:"); 456 for (size_t i = 1; i < LogTag::Count; i++) { 457 out->print("%s %s", (i == 1 ? "" : ","), LogTag::name(static_cast<LogTagType>(i))); 458 } 459 out->cr(); 460 461 LogTagSet::describe_tagsets(out); 462 } 463 464 void LogConfiguration::describe_current_configuration(outputStream* out){ 465 out->print_cr("Log output configuration:"); 466 for (size_t i = 0; i < _n_outputs; i++) { 467 out->print("#" SIZE_FORMAT ": ", i); 468 _outputs[i]->describe(out); 469 out->cr(); 470 } 471 } 472 473 void LogConfiguration::describe(outputStream* out) { 474 describe_available(out); 475 ConfigurationLock cl; 476 describe_current_configuration(out); 477 } 478 479 void LogConfiguration::print_command_line_help(FILE* out) { 480 jio_fprintf(out, "-Xlog Usage: -Xlog[:[what][:[output][:[decorators][:output-options]]]]\n" 481 "\t where 'what' is a combination of tags and levels of the form tag1[+tag2...][*][=level][,...]\n" 482 "\t Unless wildcard (*) is specified, only log messages tagged with exactly the tags specified will be matched.\n\n"); 483 484 jio_fprintf(out, "Available log levels:\n"); 485 for (size_t i = 0; i < LogLevel::Count; i++) { 486 jio_fprintf(out, "%s %s", (i == 0 ? "" : ","), LogLevel::name(static_cast<LogLevelType>(i))); 487 } 488 489 jio_fprintf(out, "\n\nAvailable log decorators: \n"); 490 for (size_t i = 0; i < LogDecorators::Count; i++) { 491 LogDecorators::Decorator d = static_cast<LogDecorators::Decorator>(i); 492 jio_fprintf(out, "%s %s (%s)", (i == 0 ? "" : ","), LogDecorators::name(d), LogDecorators::abbreviation(d)); 493 } 494 jio_fprintf(out, "\n Decorators can also be specified as 'none' for no decoration.\n\n"); 495 496 jio_fprintf(out, "Available log tags:\n"); 497 for (size_t i = 1; i < LogTag::Count; i++) { 498 jio_fprintf(out, "%s %s", (i == 1 ? "" : ","), LogTag::name(static_cast<LogTagType>(i))); 499 } 500 jio_fprintf(out, "\n Specifying 'all' instead of a tag combination matches all tag combinations.\n\n"); 501 502 fileStream stream(out, false); 503 LogTagSet::describe_tagsets(&stream); 504 505 jio_fprintf(out, "\nAvailable log outputs:\n" 506 " stdout, stderr, file=<filename>\n" 507 " Specifying %%p and/or %%t in the filename will expand to the JVM's PID and startup timestamp, respectively.\n\n" 508 509 "Some examples:\n" 510 " -Xlog\n" 511 "\t Log all messages using 'info' level to stdout with 'uptime', 'levels' and 'tags' decorations.\n" 512 "\t (Equivalent to -Xlog:all=info:stdout:uptime,levels,tags).\n\n" 513 514 " -Xlog:gc\n" 515 "\t Log messages tagged with 'gc' tag using 'info' level to stdout, with default decorations.\n\n" 516 517 " -Xlog:gc,safepoint\n" 518 "\t Log messages tagged either with 'gc' or 'safepoint' tags, both using 'info' level, to stdout, with default decorations.\n" 519 "\t (Messages tagged with both 'gc' and 'safepoint' will not be logged.)\n\n" 520 521 " -Xlog:gc+ref=debug\n" 522 "\t Log messages tagged with both 'gc' and 'ref' tags, using 'debug' level, to stdout, with default decorations.\n" 523 "\t (Messages tagged only with one of the two tags will not be logged.)\n\n" 524 525 " -Xlog:gc=debug:file=gc.txt:none\n" 526 "\t Log messages tagged with 'gc' tag using 'debug' level to file 'gc.txt' with no decorations.\n\n" 527 528 " -Xlog:gc=trace:file=gctrace.txt:uptimemillis,pids:filecount=5,filesize=1m\n" 529 "\t Log messages tagged with 'gc' tag using 'trace' level to a rotating fileset of 5 files of size 1MB,\n" 530 "\t using the base name 'gctrace.txt', with 'uptimemillis' and 'pid' decorations.\n\n" 531 532 " -Xlog:gc::uptime,tid\n" 533 "\t Log messages tagged with 'gc' tag using 'info' level to output 'stdout', using 'uptime' and 'tid' decorations.\n\n" 534 535 " -Xlog:gc*=info,safepoint*=off\n" 536 "\t Log messages tagged with at least 'gc' using 'info' level, but turn off logging of messages tagged with 'safepoint'.\n" 537 "\t (Messages tagged with both 'gc' and 'safepoint' will not be logged.)\n\n" 538 539 " -Xlog:disable -Xlog:safepoint=trace:safepointtrace.txt\n" 540 "\t Turn off all logging, including warnings and errors,\n" 541 "\t and then enable messages tagged with 'safepoint' using 'trace' level to file 'safepointtrace.txt'.\n"); 542 } 543 544 void LogConfiguration::rotate_all_outputs() { 545 // Start from index 2 since neither stdout nor stderr can be rotated. 546 for (size_t idx = 2; idx < _n_outputs; idx++) { 547 _outputs[idx]->force_rotate(); 548 } 549 } 550 551 void LogConfiguration::register_update_listener(UpdateListenerFunction cb) { 552 assert(cb != NULL, "Should not register NULL as listener"); 553 ConfigurationLock cl; 554 size_t idx = _n_listener_callbacks++; 555 _listener_callbacks = REALLOC_C_HEAP_ARRAY(UpdateListenerFunction, 556 _listener_callbacks, 557 _n_listener_callbacks, 558 mtLogging); 559 _listener_callbacks[idx] = cb; 560 } 561 562 void LogConfiguration::notify_update_listeners() { 563 assert(ConfigurationLock::current_thread_has_lock(), "notify_update_listeners must be called in ConfigurationLock scope (lock held)"); 564 for (size_t i = 0; i < _n_listener_callbacks; i++) { 565 _listener_callbacks[i](); 566 } 567 }