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