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