jdk

1
/*
2
 * Copyright (c) 2015, 2024, 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 "jvm.h"
26
#include "logging/log.hpp"
27
#include "logging/logAsyncWriter.hpp"
28
#include "logging/logConfiguration.hpp"
29
#include "logging/logFileOutput.hpp"
30
#include "memory/allocation.inline.hpp"
31
#include "runtime/arguments.hpp"
32
#include "runtime/os.hpp"
33
#include "utilities/defaultStream.hpp"
34
#include "utilities/globalDefinitions.hpp"
35

36
const char* const LogFileOutput::Prefix = "file=";
37
const char* const LogFileOutput::FileOpenMode = "a";
38
const char* const LogFileOutput::PidFilenamePlaceholder = "%p";
39
const char* const LogFileOutput::TimestampFilenamePlaceholder = "%t";
40
const char* const LogFileOutput::TimestampFormat = "%Y-%m-%d_%H-%M-%S";
41
const char* const LogFileOutput::HostnameFilenamePlaceholder = "%hn";
42
const char* const LogFileOutput::FileSizeOptionKey = "filesize";
43
const char* const LogFileOutput::FileCountOptionKey = "filecount";
44
char        LogFileOutput::_pid_str[PidBufferSize];
45
char        LogFileOutput::_vm_start_time_str[StartTimeBufferSize];
46

47
LogFileOutput::LogFileOutput(const char* name)
48
    : LogFileStreamOutput(nullptr), _name(os::strdup_check_oom(name, mtLogging)),
49
      _file_name(nullptr), _archive_name(nullptr), _current_file(0),
50
      _file_count(DefaultFileCount), _is_default_file_count(true), _archive_name_len(0),
51
      _rotate_size(DefaultFileSize), _current_size(0), _rotation_semaphore(1) {
52
  assert(strstr(name, Prefix) == name, "invalid output name '%s': missing prefix: %s", name, Prefix);
53
  _file_name = make_file_name(name + strlen(Prefix), _pid_str, _vm_start_time_str);
54
}
55

56
const char* LogFileOutput::cur_log_file_name() {
57
  if (strlen(_archive_name) == 0) {
58
    return _file_name;
59
  } else {
60
    return _archive_name;
61
  }
62
}
63

64
void LogFileOutput::set_file_name_parameters(jlong vm_start_time) {
65
  int res = jio_snprintf(_pid_str, sizeof(_pid_str), "%d", os::current_process_id());
66
  assert(res > 0, "PID buffer too small");
67

68
  struct tm local_time;
69
  time_t utc_time = vm_start_time / 1000;
70
  os::localtime_pd(&utc_time, &local_time);
71
  res = (int)strftime(_vm_start_time_str, sizeof(_vm_start_time_str), TimestampFormat, &local_time);
72
  assert(res > 0, "VM start time buffer too small.");
73
}
74

75
LogFileOutput::~LogFileOutput() {
76
  if (_stream != nullptr) {
77
    if (fclose(_stream) != 0) {
78
      jio_fprintf(defaultStream::error_stream(), "Could not close log file '%s' (%s).\n",
79
                  _file_name, os::strerror(errno));
80
    }
81
  }
82
  os::free(_archive_name);
83
  os::free(_file_name);
84
  os::free(const_cast<char*>(_name));
85
}
86

87
static size_t parse_value(const char* value_str) {
88
  char* end;
89
  unsigned long long value = strtoull(value_str, &end, 10);
90
  if (!isdigit(*value_str) || end != value_str + strlen(value_str) || value >= SIZE_MAX) {
91
    return SIZE_MAX;
92
  }
93
  return value;
94
}
95

96
static uint number_of_digits(uint number) {
97
  return number < 10 ? 1 : (number < 100 ? 2 : 3);
98
}
99

100
static bool is_regular_file(const char* filename) {
101
  struct stat st;
102
  int ret = os::stat(filename, &st);
103
  if (ret != 0) {
104
    return false;
105
  }
106
  return (st.st_mode & S_IFMT) == S_IFREG;
107
}
108

109
static bool is_fifo_file(const char* filename) {
110
  struct stat st;
111
  int ret = os::stat(filename, &st);
112
  if (ret != 0) {
113
    return false;
114
  }
115
  return S_ISFIFO(st.st_mode);
116
}
117

118
// Try to find the next number that should be used for file rotation.
119
// Return UINT_MAX on error.
120
static uint next_file_number(const char* filename,
121
                             uint number_of_digits,
122
                             uint filecount,
123
                             outputStream* errstream) {
124
  bool found = false;
125
  uint next_num = 0;
126

127
  // len is filename + dot + digits + null char
128
  size_t len = strlen(filename) + number_of_digits + 2;
129
  char* archive_name = NEW_C_HEAP_ARRAY(char, len, mtLogging);
130
  char* oldest_name = NEW_C_HEAP_ARRAY(char, len, mtLogging);
131

132
  for (uint i = 0; i < filecount; i++) {
133
    int ret = jio_snprintf(archive_name, len, "%s.%0*u",
134
                           filename, number_of_digits, i);
135
    assert(ret > 0 && static_cast<size_t>(ret) == len - 1,
136
           "incorrect buffer length calculation");
137

138
    if (os::file_exists(archive_name) && !is_regular_file(archive_name)) {
139
      // We've encountered something that's not a regular file among the
140
      // possible file rotation targets. Fail immediately to prevent
141
      // problems later.
142
      errstream->print_cr("Possible rotation target file '%s' already exists "
143
                          "but is not a regular file.", archive_name);
144
      next_num = UINT_MAX;
145
      break;
146
    }
147

148
    // Stop looking if we find an unused file name
149
    if (!os::file_exists(archive_name)) {
150
      next_num = i;
151
      found = true;
152
      break;
153
    }
154

155
    // Keep track of oldest existing log file
156
    if (!found
157
        || os::compare_file_modified_times(oldest_name, archive_name) > 0) {
158
      strcpy(oldest_name, archive_name);
159
      next_num = i;
160
      found = true;
161
    }
162
  }
163

164
  FREE_C_HEAP_ARRAY(char, oldest_name);
165
  FREE_C_HEAP_ARRAY(char, archive_name);
166
  return next_num;
167
}
168

169
bool LogFileOutput::set_option(const char* key, const char* value, outputStream* errstream) {
170
  bool success = LogFileStreamOutput::set_option(key, value, errstream);
171
  if (!success) {
172
    if (strcmp(FileCountOptionKey, key) == 0) {
173
      size_t sizeval = parse_value(value);
174
      if (sizeval > MaxRotationFileCount) {
175
        errstream->print_cr("Invalid option: %s must be in range [0, %u]",
176
                            FileCountOptionKey,
177
                            MaxRotationFileCount);
178
      } else {
179
        _file_count = static_cast<uint>(sizeval);
180
        _is_default_file_count = false;
181
        success = true;
182
      }
183
    } else if (strcmp(FileSizeOptionKey, key) == 0) {
184
      julong longval;
185
      success = Arguments::atojulong(value, &longval);
186
      if (!success || (longval > SIZE_MAX)) {
187
        errstream->print_cr("Invalid option: %s must be in range [0, "
188
                            SIZE_FORMAT "]", FileSizeOptionKey, (size_t)SIZE_MAX);
189
        success = false;
190
      } else {
191
        _rotate_size = static_cast<size_t>(longval);
192
        success = true;
193
      }
194
    }
195
  }
196
  return success;
197
}
198

199
bool LogFileOutput::initialize(const char* options, outputStream* errstream) {
200
  if (!parse_options(options, errstream)) {
201
    return false;
202
  }
203

204
  bool file_exist = os::file_exists(_file_name);
205
  if (file_exist && _is_default_file_count && is_fifo_file(_file_name)) {
206
    _file_count = 0; // Prevent file rotation for fifo's such as named pipes.
207
  }
208

209
  if (_file_count > 0) {
210
    // compute digits with filecount - 1 since numbers will start from 0
211
    _file_count_max_digits = number_of_digits(_file_count - 1);
212
    _archive_name_len = 2 + strlen(_file_name) + _file_count_max_digits;
213
    _archive_name = NEW_C_HEAP_ARRAY(char, _archive_name_len, mtLogging);
214
    _archive_name[0] = 0;
215
  }
216

217
  log_trace(logging)("Initializing logging to file '%s' (filecount: %u"
218
                     ", filesize: " SIZE_FORMAT " KiB).",
219
                     _file_name, _file_count, _rotate_size / K);
220

221
  if (_file_count > 0 && file_exist) {
222
    if (!is_regular_file(_file_name)) {
223
      errstream->print_cr("Unable to log to file %s with log file rotation: "
224
                          "%s is not a regular file",
225
                          _file_name, _file_name);
226
      return false;
227
    }
228
    _current_file = next_file_number(_file_name,
229
                                     _file_count_max_digits,
230
                                     _file_count,
231
                                     errstream);
232
    if (_current_file == UINT_MAX) {
233
      return false;
234
    }
235
    log_trace(logging)("Existing log file found, saving it as '%s.%0*u'",
236
                       _file_name, _file_count_max_digits, _current_file);
237
    archive();
238
    increment_file_count();
239
  }
240

241
  _stream = os::fopen(_file_name, FileOpenMode);
242
  if (_stream == nullptr) {
243
    errstream->print_cr("Error opening log file '%s': %s",
244
                        _file_name, os::strerror(errno));
245
    return false;
246
  }
247

248
  if (_file_count == 0 && is_regular_file(_file_name)) {
249
    log_trace(logging)("Truncating log file");
250
    os::ftruncate(os::get_fileno(_stream), 0);
251
  }
252

253
  return true;
254
}
255

256
class RotationLocker : public StackObj {
257
  Semaphore& _sem;
258

259
 public:
260
  RotationLocker(Semaphore& sem) : _sem(sem) {
261
    sem.wait();
262
  }
263

264
  ~RotationLocker() {
265
    _sem.signal();
266
  }
267
};
268

269
int LogFileOutput::write_blocking(const LogDecorations& decorations, const char* msg) {
270
  RotationLocker lock(_rotation_semaphore);
271
  if (_stream == nullptr) {
272
    // An error has occurred with this output, avoid writing to it.
273
    return 0;
274
  }
275

276
  int written = write_internal(decorations, msg);
277
  // Need to flush to the filesystem before should_rotate()
278
  written = flush() ? written : -1;
279
  if (written > 0) {
280
    _current_size += written;
281

282
    if (should_rotate()) {
283
      rotate();
284
    }
285
  }
286

287
  return written;
288
}
289

290
int LogFileOutput::write(const LogDecorations& decorations, const char* msg) {
291
  if (_stream == nullptr) {
292
    // An error has occurred with this output, avoid writing to it.
293
    return 0;
294
  }
295

296
  AsyncLogWriter* aio_writer = AsyncLogWriter::instance();
297
  if (aio_writer != nullptr) {
298
    aio_writer->enqueue(*this, decorations, msg);
299
    return 0;
300
  }
301

302
  return write_blocking(decorations, msg);
303
}
304

305
int LogFileOutput::write(LogMessageBuffer::Iterator msg_iterator) {
306
  if (_stream == nullptr) {
307
    // An error has occurred with this output, avoid writing to it.
308
    return 0;
309
  }
310

311
  AsyncLogWriter* aio_writer = AsyncLogWriter::instance();
312
  if (aio_writer != nullptr) {
313
    aio_writer->enqueue(*this, msg_iterator);
314
    return 0;
315
  }
316

317
  RotationLocker lock(_rotation_semaphore);
318
  int written = LogFileStreamOutput::write(msg_iterator);
319
  if (written > 0) {
320
    _current_size += written;
321

322
    if (should_rotate()) {
323
      rotate();
324
    }
325
  }
326

327
  return written;
328
}
329

330
void LogFileOutput::archive() {
331
  assert(_archive_name != nullptr && _archive_name_len > 0, "Rotation must be configured before using this function.");
332
  int ret = jio_snprintf(_archive_name, _archive_name_len, "%s.%0*u",
333
                         _file_name, _file_count_max_digits, _current_file);
334
  assert(ret >= 0, "Buffer should always be large enough");
335

336
  // Attempt to remove possibly existing archived log file before we rename.
337
  // Don't care if it fails, we really only care about the rename that follows.
338
  remove(_archive_name);
339

340
  // Rename the file from ex hotspot.log to hotspot.log.2
341
  if (rename(_file_name, _archive_name) == -1) {
342
    jio_fprintf(defaultStream::error_stream(), "Could not rename log file '%s' to '%s' (%s).\n",
343
                _file_name, _archive_name, os::strerror(errno));
344
  }
345
}
346

347
void LogFileOutput::force_rotate() {
348
  if (_file_count == 0) {
349
    // Rotation not possible
350
    return;
351
  }
352

353
  RotationLocker lock(_rotation_semaphore);
354
  rotate();
355
}
356

357
void LogFileOutput::rotate() {
358
  if (fclose(_stream)) {
359
    jio_fprintf(defaultStream::error_stream(), "Error closing file '%s' during log rotation (%s).\n",
360
                _file_name, os::strerror(errno));
361
  }
362

363
  // Archive the current log file
364
  archive();
365

366
  // Open the active log file using the same stream as before
367
  _stream = os::fopen(_file_name, FileOpenMode);
368
  if (_stream == nullptr) {
369
    jio_fprintf(defaultStream::error_stream(), "Could not reopen file '%s' during log rotation (%s).\n",
370
                _file_name, os::strerror(errno));
371
    return;
372
  }
373

374
  // Reset accumulated size, increase current file counter, and check for file count wrap-around.
375
  _current_size = 0;
376
  increment_file_count();
377
}
378

379
char* LogFileOutput::make_file_name(const char* file_name,
380
                                    const char* pid_string,
381
                                    const char* timestamp_string) {
382
  char hostname_string[HostnameBufferSize];
383
  char* result = nullptr;
384

385
  // Lets start finding out if we have any %p, %t and/or %hn in the name.
386
  // We will only replace the first occurrence of any placeholder
387
  const char* pid = strstr(file_name, PidFilenamePlaceholder);
388
  const char* timestamp = strstr(file_name, TimestampFilenamePlaceholder);
389
  const char* hostname = strstr(file_name, HostnameFilenamePlaceholder);
390

391
  if (pid == nullptr && timestamp == nullptr && hostname == nullptr) {
392
    // We found no place-holders, return the simple filename
393
    return os::strdup_check_oom(file_name, mtLogging);
394
  }
395

396
  // At least one of the place-holders were found in the file_name
397
  size_t result_len =  strlen(file_name);
398
  if (pid != nullptr) {
399
    result_len -= strlen(PidFilenamePlaceholder);
400
    result_len += strlen(pid_string);
401
  }
402
  if (timestamp != nullptr) {
403
    result_len -= strlen(TimestampFilenamePlaceholder);
404
    result_len += strlen(timestamp_string);
405
  }
406
  if (hostname != nullptr) {
407
    if (!os::get_host_name(hostname_string, sizeof(hostname_string))) {
408
      int res = jio_snprintf(hostname_string, sizeof(hostname_string), "unknown-host");
409
      assert(res > 0, "Hostname buffer too small");
410
    }
411
    result_len -= strlen(HostnameFilenamePlaceholder);
412
    result_len += strlen(hostname_string);
413
  }
414
  // Allocate the new buffer, size it to hold all we want to put in there +1.
415
  result = NEW_C_HEAP_ARRAY(char, result_len + 1, mtLogging);
416

417
  // Assemble the strings
418
  size_t file_name_pos = 0;
419
  size_t i = 0;
420
  while (i < result_len) {
421
    if (file_name[file_name_pos] == '%') {
422
      // Replace the first occurrence of any placeholder
423
      if (pid != nullptr && strncmp(&file_name[file_name_pos],
424
                                    PidFilenamePlaceholder,
425
                                    strlen(PidFilenamePlaceholder)) == 0) {
426
        strcpy(result + i, pid_string);
427
        i += strlen(pid_string);
428
        file_name_pos += strlen(PidFilenamePlaceholder);
429
        pid = nullptr;
430
        continue;
431
      }
432
      if (timestamp != nullptr && strncmp(&file_name[file_name_pos],
433
                                          TimestampFilenamePlaceholder,
434
                                          strlen(TimestampFilenamePlaceholder)) == 0) {
435
        strcpy(result + i, timestamp_string);
436
        i += strlen(timestamp_string);
437
        file_name_pos += strlen(TimestampFilenamePlaceholder);
438
        timestamp = nullptr;
439
        continue;
440
      }
441
      if (hostname != nullptr && strncmp(&file_name[file_name_pos],
442
                                         HostnameFilenamePlaceholder,
443
                                         strlen(HostnameFilenamePlaceholder)) == 0) {
444
        strcpy(result + i, hostname_string);
445
        i += strlen(hostname_string);
446
        file_name_pos += strlen(HostnameFilenamePlaceholder);
447
        hostname = nullptr;
448
        continue;
449
      }
450
    }
451
    // Else, copy char by char of the original file
452
    result[i++] = file_name[file_name_pos++];
453
  }
454
  assert(i == result_len, "should be");
455
  assert(file_name[file_name_pos] == '\0', "should be");
456

457
  // Add terminating char
458
  result[result_len] = '\0';
459
  return result;
460
}
461

462
void LogFileOutput::describe(outputStream *out) {
463
  LogFileStreamOutput::describe(out);
464
  out->print(",filecount=%u,filesize=" SIZE_FORMAT "%s,async=%s", _file_count,
465
             byte_size_in_proper_unit(_rotate_size),
466
             proper_unit_for_byte_size(_rotate_size),
467
             LogConfiguration::is_async_mode() ? "true" : "false");
468
}
469