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