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/logFileOutput.hpp"
  28 #include "memory/allocation.inline.hpp"
  29 #include "prims/jvm.h"
  30 #include "runtime/arguments.hpp"
  31 #include "runtime/os.inline.hpp"
  32 #include "utilities/globalDefinitions.hpp"
  33 #include "utilities/defaultStream.hpp"
  34 
  35 const char* LogFileOutput::Prefix = "file=";
  36 const char* LogFileOutput::FileOpenMode = "a";
  37 const char* LogFileOutput::PidFilenamePlaceholder = "%p";
  38 const char* LogFileOutput::TimestampFilenamePlaceholder = "%t";
  39 const char* LogFileOutput::TimestampFormat = "%Y-%m-%d_%H-%M-%S";
  40 const char* LogFileOutput::FileSizeOptionKey = "filesize";
  41 const char* LogFileOutput::FileCountOptionKey = "filecount";
  42 char        LogFileOutput::_pid_str[PidBufferSize];
  43 char        LogFileOutput::_vm_start_time_str[StartTimeBufferSize];
  44 
  45 LogFileOutput::LogFileOutput(const char* name)
  46     : LogFileStreamOutput(NULL), _name(os::strdup_check_oom(name, mtLogging)),
  47       _file_name(NULL), _archive_name(NULL), _archive_name_len(0),
  48       _rotate_size(DefaultFileSize), _file_count(DefaultFileCount),
  49       _current_size(0), _current_file(0), _rotation_semaphore(1) {
  50   assert(strstr(name, Prefix) == name, "invalid output name '%s': missing prefix: %s", name, Prefix);
  51   _file_name = make_file_name(name + strlen(Prefix), _pid_str, _vm_start_time_str);
  52 }
  53 
  54 void LogFileOutput::set_file_name_parameters(jlong vm_start_time) {
  55   int res = jio_snprintf(_pid_str, sizeof(_pid_str), "%d", os::current_process_id());
  56   assert(res > 0, "PID buffer too small");
  57 
  58   struct tm local_time;
  59   time_t utc_time = vm_start_time / 1000;
  60   os::localtime_pd(&utc_time, &local_time);
  61   res = (int)strftime(_vm_start_time_str, sizeof(_vm_start_time_str), TimestampFormat, &local_time);
  62   assert(res > 0, "VM start time buffer too small.");
  63 }
  64 
  65 LogFileOutput::~LogFileOutput() {
  66   if (_stream != NULL) {
  67     if (fclose(_stream) != 0) {
  68       jio_fprintf(defaultStream::error_stream(), "Could not close log file '%s' (%s).\n",
  69                   _file_name, os::strerror(errno));
  70     }
  71   }
  72   os::free(_archive_name);
  73   os::free(_file_name);
  74   os::free(const_cast<char*>(_name));
  75 }
  76 
  77 static size_t parse_value(const char* value_str) {
  78   char* end;
  79   unsigned long long value = strtoull(value_str, &end, 10);
  80   if (!isdigit(*value_str) || end != value_str + strlen(value_str) || value >= SIZE_MAX) {
  81     return SIZE_MAX;
  82   }
  83   return value;
  84 }
  85 
  86 static bool file_exists(const char* filename) {
  87   struct stat dummy_stat;
  88   return os::stat(filename, &dummy_stat) == 0;
  89 }
  90 
  91 static uint number_of_digits(uint number) {
  92   return number < 10 ? 1 : (number < 100 ? 2 : 3);
  93 }
  94 
  95 static bool is_regular_file(const char* filename) {
  96   struct stat st;
  97   int ret = os::stat(filename, &st);
  98   if (ret != 0) {
  99     return false;
 100   }
 101   return (st.st_mode & S_IFMT) == S_IFREG;
 102 }
 103 
 104 // Try to find the next number that should be used for file rotation.
 105 // Return UINT_MAX on error.
 106 static uint next_file_number(const char* filename,
 107                              uint number_of_digits,
 108                              uint filecount,
 109                              outputStream* errstream) {
 110   bool found = false;
 111   uint next_num = 0;
 112 
 113   // len is filename + dot + digits + null char
 114   size_t len = strlen(filename) + number_of_digits + 2;
 115   char* archive_name = NEW_C_HEAP_ARRAY(char, len, mtLogging);
 116   char* oldest_name = NEW_C_HEAP_ARRAY(char, len, mtLogging);
 117 
 118   for (uint i = 0; i < filecount; i++) {
 119     int ret = jio_snprintf(archive_name, len, "%s.%0*u",
 120                            filename, number_of_digits, i);
 121     assert(ret > 0 && static_cast<size_t>(ret) == len - 1,
 122            "incorrect buffer length calculation");
 123 
 124     if (file_exists(archive_name) && !is_regular_file(archive_name)) {
 125       // We've encountered something that's not a regular file among the
 126       // possible file rotation targets. Fail immediately to prevent
 127       // problems later.
 128       errstream->print_cr("Possible rotation target file '%s' already exists "
 129                           "but is not a regular file.", archive_name);
 130       next_num = UINT_MAX;
 131       break;
 132     }
 133 
 134     // Stop looking if we find an unused file name
 135     if (!file_exists(archive_name)) {
 136       next_num = i;
 137       found = true;
 138       break;
 139     }
 140 
 141     // Keep track of oldest existing log file
 142     if (!found
 143         || os::compare_file_modified_times(oldest_name, archive_name) > 0) {
 144       strcpy(oldest_name, archive_name);
 145       next_num = i;
 146       found = true;
 147     }
 148   }
 149 
 150   FREE_C_HEAP_ARRAY(char, oldest_name);
 151   FREE_C_HEAP_ARRAY(char, archive_name);
 152   return next_num;
 153 }
 154 
 155 bool LogFileOutput::parse_options(const char* options, outputStream* errstream) {
 156   if (options == NULL || strlen(options) == 0) {
 157     return true;
 158   }
 159   bool success = true;
 160   char* opts = os::strdup_check_oom(options, mtLogging);
 161 
 162   char* comma_pos;
 163   char* pos = opts;
 164   do {
 165     comma_pos = strchr(pos, ',');
 166     if (comma_pos != NULL) {
 167       *comma_pos = '\0';
 168     }
 169 
 170     char* equals_pos = strchr(pos, '=');
 171     if (equals_pos == NULL) {
 172       success = false;
 173       break;
 174     }
 175     char* key = pos;
 176     char* value_str = equals_pos + 1;
 177     *equals_pos = '\0';
 178 
 179     if (strcmp(FileCountOptionKey, key) == 0) {
 180       size_t value = parse_value(value_str);
 181       if (value > MaxRotationFileCount) {
 182         errstream->print_cr("Invalid option: %s must be in range [0, %u]",
 183                             FileCountOptionKey,
 184                             MaxRotationFileCount);
 185         success = false;
 186         break;
 187       }
 188       _file_count = static_cast<uint>(value);
 189     } else if (strcmp(FileSizeOptionKey, key) == 0) {
 190       julong value;
 191       success = Arguments::atojulong(value_str, &value);
 192       if (!success || (value > SIZE_MAX)) {
 193         errstream->print_cr("Invalid option: %s must be in range [0, "
 194                             SIZE_FORMAT "]", FileSizeOptionKey, SIZE_MAX);
 195         success = false;
 196         break;
 197       }
 198       _rotate_size = static_cast<size_t>(value);
 199     } else {
 200       errstream->print_cr("Invalid option '%s' for log file output.", key);
 201       success = false;
 202       break;
 203     }
 204     pos = comma_pos + 1;
 205   } while (comma_pos != NULL);
 206 
 207   os::free(opts);
 208   return success;
 209 }
 210 
 211 bool LogFileOutput::initialize(const char* options, outputStream* errstream) {
 212   if (!parse_options(options, errstream)) {
 213     return false;
 214   }
 215 
 216   if (_file_count > 0) {
 217     // compute digits with filecount - 1 since numbers will start from 0
 218     _file_count_max_digits = number_of_digits(_file_count - 1);
 219     _archive_name_len = 2 + strlen(_file_name) + _file_count_max_digits;
 220     _archive_name = NEW_C_HEAP_ARRAY(char, _archive_name_len, mtLogging);
 221   }
 222 
 223   log_trace(logging)("Initializing logging to file '%s' (filecount: %u"
 224                      ", filesize: " SIZE_FORMAT " KiB).",
 225                      _file_name, _file_count, _rotate_size / K);
 226 
 227   if (_file_count > 0 && file_exists(_file_name)) {
 228     if (!is_regular_file(_file_name)) {
 229       errstream->print_cr("Unable to log to file %s with log file rotation: "
 230                           "%s is not a regular file",
 231                           _file_name, _file_name);
 232       return false;
 233     }
 234     _current_file = next_file_number(_file_name,
 235                                      _file_count_max_digits,
 236                                      _file_count,
 237                                      errstream);
 238     if (_current_file == UINT_MAX) {
 239       return false;
 240     }
 241     log_trace(logging)("Existing log file found, saving it as '%s.%0*u'",
 242                        _file_name, _file_count_max_digits, _current_file);
 243     archive();
 244     increment_file_count();
 245   }
 246 
 247   _stream = fopen(_file_name, FileOpenMode);
 248   if (_stream == NULL) {
 249     errstream->print_cr("Error opening log file '%s': %s",
 250                         _file_name, strerror(errno));
 251     return false;
 252   }
 253 
 254   if (_file_count == 0 && is_regular_file(_file_name)) {
 255     log_trace(logging)("Truncating log file");
 256     os::ftruncate(os::get_fileno(_stream), 0);
 257   }
 258 
 259   return true;
 260 }
 261 
 262 int LogFileOutput::write(const LogDecorations& decorations, const char* msg) {
 263   if (_stream == NULL) {
 264     // An error has occurred with this output, avoid writing to it.
 265     return 0;
 266   }
 267 
 268   _rotation_semaphore.wait();
 269   int written = LogFileStreamOutput::write(decorations, msg);
 270   _current_size += written;
 271 
 272   if (should_rotate()) {
 273     rotate();
 274   }
 275   _rotation_semaphore.signal();
 276 
 277   return written;
 278 }
 279 
 280 int LogFileOutput::write(LogMessageBuffer::Iterator msg_iterator) {
 281   if (_stream == NULL) {
 282     // An error has occurred with this output, avoid writing to it.
 283     return 0;
 284   }
 285 
 286   _rotation_semaphore.wait();
 287   int written = LogFileStreamOutput::write(msg_iterator);
 288   _current_size += written;
 289 
 290   if (should_rotate()) {
 291     rotate();
 292   }
 293   _rotation_semaphore.signal();
 294 
 295   return written;
 296 }
 297 
 298 void LogFileOutput::archive() {
 299   assert(_archive_name != NULL && _archive_name_len > 0, "Rotation must be configured before using this function.");
 300   int ret = jio_snprintf(_archive_name, _archive_name_len, "%s.%0*u",
 301                          _file_name, _file_count_max_digits, _current_file);
 302   assert(ret >= 0, "Buffer should always be large enough");
 303 
 304   // Attempt to remove possibly existing archived log file before we rename.
 305   // Don't care if it fails, we really only care about the rename that follows.
 306   remove(_archive_name);
 307 
 308   // Rename the file from ex hotspot.log to hotspot.log.2
 309   if (rename(_file_name, _archive_name) == -1) {
 310     jio_fprintf(defaultStream::error_stream(), "Could not rename log file '%s' to '%s' (%s).\n",
 311                 _file_name, _archive_name, os::strerror(errno));
 312   }
 313 }
 314 
 315 void LogFileOutput::force_rotate() {
 316   if (_file_count == 0) {
 317     // Rotation not possible
 318     return;
 319   }
 320   _rotation_semaphore.wait();
 321   rotate();
 322   _rotation_semaphore.signal();
 323 }
 324 
 325 void LogFileOutput::rotate() {
 326 
 327   if (fclose(_stream)) {
 328     jio_fprintf(defaultStream::error_stream(), "Error closing file '%s' during log rotation (%s).\n",
 329                 _file_name, os::strerror(errno));
 330   }
 331 
 332   // Archive the current log file
 333   archive();
 334 
 335   // Open the active log file using the same stream as before
 336   _stream = fopen(_file_name, FileOpenMode);
 337   if (_stream == NULL) {
 338     jio_fprintf(defaultStream::error_stream(), "Could not reopen file '%s' during log rotation (%s).\n",
 339                 _file_name, os::strerror(errno));
 340     return;
 341   }
 342 
 343   // Reset accumulated size, increase current file counter, and check for file count wrap-around.
 344   _current_size = 0;
 345   increment_file_count();
 346 }
 347 
 348 char* LogFileOutput::make_file_name(const char* file_name,
 349                                     const char* pid_string,
 350                                     const char* timestamp_string) {
 351   char* result = NULL;
 352 
 353   // Lets start finding out if we have any %d and/or %t in the name.
 354   // We will only replace the first occurrence of any placeholder
 355   const char* pid = strstr(file_name, PidFilenamePlaceholder);
 356   const char* timestamp = strstr(file_name, TimestampFilenamePlaceholder);
 357 
 358   if (pid == NULL && timestamp == NULL) {
 359     // We found no place-holders, return the simple filename
 360     return os::strdup_check_oom(file_name, mtLogging);
 361   }
 362 
 363   // At least one of the place-holders were found in the file_name
 364   const char* first = "";
 365   size_t first_pos = SIZE_MAX;
 366   size_t first_replace_len = 0;
 367 
 368   const char* second = "";
 369   size_t second_pos = SIZE_MAX;
 370   size_t second_replace_len = 0;
 371 
 372   // If we found a %p, then setup our variables accordingly
 373   if (pid != NULL) {
 374     if (timestamp == NULL || pid < timestamp) {
 375       first = pid_string;
 376       first_pos = pid - file_name;
 377       first_replace_len = strlen(PidFilenamePlaceholder);
 378     } else {
 379       second = pid_string;
 380       second_pos = pid - file_name;
 381       second_replace_len = strlen(PidFilenamePlaceholder);
 382     }
 383   }
 384 
 385   if (timestamp != NULL) {
 386     if (pid == NULL || timestamp < pid) {
 387       first = timestamp_string;
 388       first_pos = timestamp - file_name;
 389       first_replace_len = strlen(TimestampFilenamePlaceholder);
 390     } else {
 391       second = timestamp_string;
 392       second_pos = timestamp - file_name;
 393       second_replace_len = strlen(TimestampFilenamePlaceholder);
 394     }
 395   }
 396 
 397   size_t first_len = strlen(first);
 398   size_t second_len = strlen(second);
 399 
 400   // Allocate the new buffer, size it to hold all we want to put in there +1.
 401   size_t result_len =  strlen(file_name) + first_len - first_replace_len + second_len - second_replace_len;
 402   result = NEW_C_HEAP_ARRAY(char, result_len + 1, mtLogging);
 403 
 404   // Assemble the strings
 405   size_t file_name_pos = 0;
 406   size_t i = 0;
 407   while (i < result_len) {
 408     if (file_name_pos == first_pos) {
 409       // We are in the range of the first placeholder
 410       strcpy(result + i, first);
 411       // Bump output buffer position with length of replacing string
 412       i += first_len;
 413       // Bump source buffer position to skip placeholder
 414       file_name_pos += first_replace_len;
 415     } else if (file_name_pos == second_pos) {
 416       // We are in the range of the second placeholder
 417       strcpy(result + i, second);
 418       i += second_len;
 419       file_name_pos += second_replace_len;
 420     } else {
 421       // Else, copy char by char of the original file
 422       result[i] = file_name[file_name_pos++];
 423       i++;
 424     }
 425   }
 426   // Add terminating char
 427   result[result_len] = '\0';
 428   return result;
 429 }
 430 
 431 void LogFileOutput::describe(outputStream *out) {
 432   LogOutput::describe(out);
 433   out->print(" ");
 434 
 435   out->print("filecount=%u,filesize=" SIZE_FORMAT "%s", _file_count,
 436              byte_size_in_proper_unit(_rotate_size),
 437              proper_unit_for_byte_size(_rotate_size));
 438 }
 439