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
35const char* const LogFileOutput::Prefix = "file=";
36const char* const LogFileOutput::FileOpenMode = "a";
37const char* const LogFileOutput::PidFilenamePlaceholder = "%p";
38const char* const LogFileOutput::TimestampFilenamePlaceholder = "%t";
39const char* const LogFileOutput::TimestampFormat = "%Y-%m-%d_%H-%M-%S";
40const char* const LogFileOutput::FileSizeOptionKey = "filesize";
41const char* const LogFileOutput::FileCountOptionKey = "filecount";
42char        LogFileOutput::_pid_str[PidBufferSize];
43char        LogFileOutput::_vm_start_time_str[StartTimeBufferSize];
44
45LogFileOutput::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
54void 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
65LogFileOutput::~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
77static 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
86static bool file_exists(const char* filename) {
87  struct stat dummy_stat;
88  return os::stat(filename, &dummy_stat) == 0;
89}
90
91static uint number_of_digits(uint number) {
92  return number < 10 ? 1 : (number < 100 ? 2 : 3);
93}
94
95static 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.
106static 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
155bool 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_t)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
211bool 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
262int 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
280int 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
298void 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
315void 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
325void 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
348char* 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
431void 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