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   LogHandle(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);
 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(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   ConfigurationLock cl;
 406   out->print_cr("Log output configuration:");
 407   for (size_t i = 0; i < _n_outputs; i++) {
 408     out->print("#" SIZE_FORMAT ": %s %s ", i, _outputs[i]->name(), _outputs[i]->config_string());
 409     if (_outputs[i]->option_string() != NULL) {
 410       out->print("%s ", _outputs[i]->option_string());
 411     }
 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,", LogDecorators::name(decorator));
 416       }
 417     }
 418     out->cr();
 419   }
 420 }
 421 
 422 void LogConfiguration::print_command_line_help(FILE* out) {
 423   jio_fprintf(out, "-Xlog Usage: -Xlog[:[what][:[output][:[decorators][:output-options]]]]\n"
 424               "\t where 'what' is a combination of tags and levels on the form tag1[+tag2...][*][=level][,...]\n"
 425               "\t Unless wildcard (*) is specified, only log messages tagged with exactly the tags specified will be matched.\n\n");
 426 
 427   jio_fprintf(out, "Available log levels:\n");
 428   for (size_t i = 0; i < LogLevel::Count; i++) {
 429     jio_fprintf(out, "%s %s", (i == 0 ? "" : ","), LogLevel::name(static_cast<LogLevelType>(i)));
 430   }
 431 
 432   jio_fprintf(out, "\n\nAvailable log decorators: \n");
 433   for (size_t i = 0; i < LogDecorators::Count; i++) {
 434     LogDecorators::Decorator d = static_cast<LogDecorators::Decorator>(i);
 435     jio_fprintf(out, "%s %s (%s)", (i == 0 ? "" : ","), LogDecorators::name(d), LogDecorators::abbreviation(d));
 436   }
 437   jio_fprintf(out, "\n Decorators can also be specified as 'none' for no decoration.\n\n");
 438 
 439   jio_fprintf(out, "Available log tags:\n");
 440   for (size_t i = 1; i < LogTag::Count; i++) {
 441     jio_fprintf(out, "%s %s", (i == 1 ? "" : ","), LogTag::name(static_cast<LogTagType>(i)));
 442   }
 443   jio_fprintf(out, "\n Specifying 'all' instead of a tag combination matches all tag combinations.\n\n");
 444 
 445   jio_fprintf(out, "Available log outputs:\n"
 446               " stdout, stderr, file=<filename>\n"
 447               " Specifying %%p and/or %%t in the filename will expand to the JVM's PID and startup timestamp, respectively.\n\n"
 448 
 449               "Some examples:\n"
 450               " -Xlog\n"
 451               "\t Log all messages using 'info' level to stdout with 'uptime', 'levels' and 'tags' decorations.\n"
 452               "\t (Equivalent to -Xlog:all=info:stdout:uptime,levels,tags).\n\n"
 453 
 454               " -Xlog:gc\n"
 455               "\t Log messages tagged with 'gc' tag using 'info' level to stdout, with default decorations.\n\n"
 456 
 457               " -Xlog:gc=debug:file=gc.txt:none\n"
 458               "\t Log messages tagged with 'gc' tag using 'debug' level to file 'gc.txt' with no decorations.\n\n"
 459 
 460               " -Xlog:gc=trace:file=gctrace.txt:uptimemillis,pids:filecount=5,filesize=1024\n"
 461               "\t Log messages tagged with 'gc' tag using 'trace' level to a rotating fileset of 5 files of size 1MB,\n"
 462               "\t using the base name 'gctrace.txt', with 'uptimemillis' and 'pid' decorations.\n\n"
 463 
 464               " -Xlog:gc::uptime,tid\n"
 465               "\t Log messages tagged with 'gc' tag using 'info' level to output 'stdout', using 'uptime' and 'tid' decorations.\n\n"
 466 
 467               " -Xlog:gc*=info,rt*=off\n"
 468               "\t Log messages tagged with at least 'gc' using 'info' level, but turn off logging of messages tagged with 'rt'.\n"
 469               "\t (Messages tagged with both 'gc' and 'rt' will not be logged.)\n\n"
 470 
 471               " -Xlog:disable -Xlog:rt=trace:rttrace.txt\n"
 472               "\t Turn off all logging, including warnings and errors,\n"
 473               "\t and then enable messages tagged with 'rt' using 'trace' level to file 'rttrace.txt'.\n");
 474 }
 475 
 476 void LogConfiguration::rotate_all_outputs() {
 477   // Start from index 2 since neither stdout nor stderr can be rotated.
 478   for (size_t idx = 2; idx < _n_outputs; idx++) {
 479     _outputs[idx]->force_rotate();
 480   }
 481 }
 482 
 483 void LogConfiguration::register_update_listener(UpdateListenerFunction cb) {
 484   assert(cb != NULL, "Should not register NULL as listener");
 485   ConfigurationLock cl;
 486   size_t idx = _n_listener_callbacks++;
 487   _listener_callbacks = REALLOC_C_HEAP_ARRAY(UpdateListenerFunction,
 488                                              _listener_callbacks,
 489                                              _n_listener_callbacks,
 490                                              mtLogging);
 491   _listener_callbacks[idx] = cb;
 492 }
 493 
 494 void LogConfiguration::notify_update_listeners() {
 495   assert(ConfigurationLock::current_thread_has_lock(), "notify_update_listeners must be called in ConfigurationLock scope (lock held)");
 496   for (size_t i = 0; i < _n_listener_callbacks; i++) {
 497     _listener_callbacks[i]();
 498   }
 499 }