8146879: Add option for handling existing log files in UL
Reviewed-by: dsamersoff, gziemski, rehn
--- a/hotspot/src/os/bsd/vm/os_bsd.cpp Mon Apr 11 09:45:03 2016 +0200
+++ b/hotspot/src/os/bsd/vm/os_bsd.cpp Mon Apr 11 12:22:09 2016 +0200
@@ -3732,6 +3732,28 @@
return ::stat(pathbuf, sbuf);
}
+static inline struct timespec get_mtime(const char* filename) {
+ struct stat st;
+ int ret = os::stat(filename, &st);
+ assert(ret == 0, "failed to stat() file '%s': %s", filename, strerror(errno));
+#ifdef __APPLE__
+ return st.st_mtimespec;
+#else
+ return st.st_mtim;
+#endif
+}
+
+int os::compare_file_modified_times(const char* file1, const char* file2) {
+ struct timespec filetime1 = get_mtime(file1);
+ struct timespec filetime2 = get_mtime(file2);
+ int diff = filetime1.tv_sec - filetime2.tv_sec;
+ if (diff == 0) {
+ return filetime1.tv_nsec - filetime2.tv_nsec;
+ }
+ return diff;
+}
+
+
bool os::check_heap(bool force) {
return true;
}
--- a/hotspot/src/os/linux/vm/os_linux.cpp Mon Apr 11 09:45:03 2016 +0200
+++ b/hotspot/src/os/linux/vm/os_linux.cpp Mon Apr 11 12:22:09 2016 +0200
@@ -6008,7 +6008,22 @@
return yes;
}
-
+static inline struct timespec get_mtime(const char* filename) {
+ struct stat st;
+ int ret = os::stat(filename, &st);
+ assert(ret == 0, "failed to stat() file '%s': %s", filename, strerror(errno));
+ return st.st_mtim;
+}
+
+int os::compare_file_modified_times(const char* file1, const char* file2) {
+ struct timespec filetime1 = get_mtime(file1);
+ struct timespec filetime2 = get_mtime(file2);
+ int diff = filetime1.tv_sec - filetime2.tv_sec;
+ if (diff == 0) {
+ return filetime1.tv_nsec - filetime2.tv_nsec;
+ }
+ return diff;
+}
/////////////// Unit tests ///////////////
--- a/hotspot/src/os/posix/vm/os_posix.cpp Mon Apr 11 09:45:03 2016 +0200
+++ b/hotspot/src/os/posix/vm/os_posix.cpp Mon Apr 11 12:22:09 2016 +0200
@@ -181,6 +181,10 @@
return vsnprintf(buf, len, fmt, args);
}
+int os::fileno(FILE* fp) {
+ return ::fileno(fp);
+}
+
void os::Posix::print_load_average(outputStream* st) {
st->print("load average:");
double loadavg[3];
--- a/hotspot/src/os/solaris/vm/os_solaris.cpp Mon Apr 11 09:45:03 2016 +0200
+++ b/hotspot/src/os/solaris/vm/os_solaris.cpp Mon Apr 11 12:22:09 2016 +0200
@@ -1827,6 +1827,19 @@
return ::stat(pathbuf, sbuf);
}
+static inline time_t get_mtime(const char* filename) {
+ struct stat st;
+ int ret = os::stat(filename, &st);
+ assert(ret == 0, "failed to stat() file '%s': %s", filename, strerror(errno));
+ return st.st_mtime;
+}
+
+int os::compare_file_modified_times(const char* file1, const char* file2) {
+ time_t t1 = get_mtime(file1);
+ time_t t2 = get_mtime(file2);
+ return t1 - t2;
+}
+
static bool _print_ascii_file(const char* filename, outputStream* st) {
int fd = ::open(filename, O_RDONLY);
if (fd == -1) {
--- a/hotspot/src/os/windows/vm/os_windows.cpp Mon Apr 11 09:45:03 2016 +0200
+++ b/hotspot/src/os/windows/vm/os_windows.cpp Mon Apr 11 12:22:09 2016 +0200
@@ -1594,6 +1594,19 @@
return ret;
}
+static inline time_t get_mtime(const char* filename) {
+ struct stat st;
+ int ret = os::stat(filename, &st);
+ assert(ret == 0, "failed to stat() file '%s': %s", filename, strerror(errno));
+ return st.st_mtime;
+}
+
+int os::compare_file_modified_times(const char* file1, const char* file2) {
+ time_t t1 = get_mtime(file1);
+ time_t t2 = get_mtime(file2);
+ return t1 - t2;
+}
+
void os::print_os_info_brief(outputStream* st) {
os::print_os_info(st);
}
@@ -4589,6 +4602,9 @@
return 0;
}
+int os::fileno(FILE* fp) {
+ return _fileno(fp);
+}
// This code is a copy of JDK's sysSync
// from src/windows/hpi/src/sys_api_md.c
--- a/hotspot/src/share/vm/logging/log.cpp Mon Apr 11 09:45:03 2016 +0200
+++ b/hotspot/src/share/vm/logging/log.cpp Mon Apr 11 12:22:09 2016 +0200
@@ -31,6 +31,7 @@
#include "gc/shared/gcTraceTime.inline.hpp"
#include "logging/log.hpp"
#include "logging/logConfiguration.hpp"
+#include "logging/logFileOutput.hpp"
#include "logging/logOutput.hpp"
#include "logging/logTagLevelExpression.hpp"
#include "logging/logTagSet.hpp"
@@ -138,6 +139,131 @@
assert_str_eq("all=off", stdoutput->config_string());
}
+static size_t number_of_lines_with_substring_in_file(const char* filename,
+ const char* substr) {
+ ResourceMark rm;
+ size_t ret = 0;
+ FILE* fp = fopen(filename, "r");
+ assert(fp != NULL, "error opening file %s: %s", filename, strerror(errno));
+
+ int buflen = 512;
+ char* buf = NEW_RESOURCE_ARRAY(char, buflen);
+ long pos = 0;
+
+ while (fgets(buf, buflen, fp) != NULL) {
+ if (buf[strlen(buf) - 1] != '\n' && !feof(fp)) {
+ // retry with a larger buffer
+ buf = REALLOC_RESOURCE_ARRAY(char, buf, buflen, buflen * 2);
+ buflen *= 2;
+ // rewind to beginning of line
+ fseek(fp, pos, SEEK_SET);
+ continue;
+ }
+ pos = ftell(fp);
+ if (strstr(buf, substr) != NULL) {
+ ret++;
+ }
+ }
+
+ fclose(fp);
+ return ret;
+}
+
+static bool file_exists(const char* filename) {
+ struct stat st;
+ return os::stat(filename, &st) == 0;
+}
+
+static void delete_file(const char* filename) {
+ if (!file_exists(filename)) {
+ return;
+ }
+ int ret = remove(filename);
+ assert(ret == 0, "failed to remove file '%s': %s", filename, strerror(errno));
+}
+
+static void create_directory(const char* name) {
+ assert(!file_exists(name), "can't create directory: %s already exists", name);
+ bool failed;
+#ifdef _WINDOWS
+ failed = !CreateDirectory(name, NULL);
+#else
+ failed = mkdir(name, 0777);
+#endif
+ assert(!failed, "failed to create directory %s", name);
+}
+
+static const char* ExpectedLine = "a (hopefully) unique log line for testing";
+
+static void init_file(const char* filename, const char* options = "") {
+ LogConfiguration::parse_log_arguments(filename, "logging=trace", "", options,
+ Log(logging)::error_stream());
+ log_debug(logging)("%s", ExpectedLine);
+ LogConfiguration::parse_log_arguments(filename, "all=off", "", "",
+ Log(logging)::error_stream());
+}
+
+void Test_log_file_startup_rotation() {
+ ResourceMark rm;
+ const size_t rotations = 5;
+ const char* filename = "start-rotate-test";
+ char* rotated_file[rotations];
+ for (size_t i = 0; i < rotations; i++) {
+ size_t len = strlen(filename) + 3;
+ rotated_file[i] = NEW_RESOURCE_ARRAY(char, len);
+ jio_snprintf(rotated_file[i], len, "%s." SIZE_FORMAT, filename, i);
+ delete_file(rotated_file[i]);
+ };
+
+ delete_file(filename);
+ init_file(filename);
+ assert(file_exists(filename),
+ "configured logging to file '%s' but file was not found", filename);
+
+ // Initialize the same file a bunch more times to trigger rotations
+ for (size_t i = 0; i < rotations; i++) {
+ init_file(filename);
+ assert(file_exists(rotated_file[i]), "existing file was not rotated");
+ }
+
+ // Remove a file and expect its slot to be re-used
+ delete_file(rotated_file[1]);
+ init_file(filename);
+ assert(file_exists(rotated_file[1]), "log file not properly rotated");
+
+ // Clean up after test
+ delete_file(filename);
+ for (size_t i = 0; i < rotations; i++) {
+ delete_file(rotated_file[i]);
+ }
+}
+
+void Test_log_file_startup_truncation() {
+ ResourceMark rm;
+ const char* filename = "start-truncate-test";
+ const char* archived_filename = "start-truncate-test.0";
+
+ delete_file(filename);
+ delete_file(archived_filename);
+
+ // Use the same log file twice and expect it to be overwritten/truncated
+ init_file(filename, "filecount=0");
+ assert(file_exists(filename), "couldn't find log file: %s", filename);
+
+ init_file(filename, "filecount=0");
+ assert(file_exists(filename), "couldn't find log file: %s", filename);
+ assert(!file_exists(archived_filename),
+ "existing log file %s was not properly truncated when filecount was 0",
+ filename);
+
+ // Verify that the file was really truncated and not just appended
+ assert(number_of_lines_with_substring_in_file(filename, ExpectedLine) == 1,
+ "log file %s appended rather than truncated", filename);
+
+ delete_file(filename);
+ delete_file(archived_filename);
+}
+
static int Test_logconfiguration_subscribe_triggered = 0;
static void Test_logconfiguration_subscribe_helper() {
@@ -741,4 +867,20 @@
Test_log_gctracetime_no_heap_no_cause();
}
+void Test_invalid_log_file() {
+ ResourceMark rm;
+ stringStream ss;
+ const char* target_name = "tmplogdir";
+
+ // Attempt to log to a directory (existing log not a regular file)
+ create_directory(target_name);
+ LogFileOutput bad_file("tmplogdir");
+ assert(bad_file.initialize("", &ss) == false, "file was initialized "
+ "when there was an existing directory with the same name");
+ assert(strstr(ss.as_string(), "tmplogdir is not a regular file") != NULL,
+ "missing expected error message, received msg: %s", ss.as_string());
+ ss.reset();
+ remove(target_name);
+}
+
#endif // PRODUCT
--- a/hotspot/src/share/vm/logging/logConfiguration.cpp Mon Apr 11 09:45:03 2016 +0200
+++ b/hotspot/src/share/vm/logging/logConfiguration.cpp Mon Apr 11 12:22:09 2016 +0200
@@ -145,7 +145,7 @@
return NULL;
}
- bool success = output->initialize(options);
+ bool success = output->initialize(options, errstream);
if (!success) {
errstream->print_cr("Initialization of output '%s' using options '%s' failed.", name, options);
delete output;
--- a/hotspot/src/share/vm/logging/logFileOutput.cpp Mon Apr 11 09:45:03 2016 +0200
+++ b/hotspot/src/share/vm/logging/logFileOutput.cpp Mon Apr 11 12:22:09 2016 +0200
@@ -41,8 +41,9 @@
LogFileOutput::LogFileOutput(const char* name)
: LogFileStreamOutput(NULL), _name(os::strdup_check_oom(name, mtLogging)),
- _file_name(NULL), _archive_name(NULL), _archive_name_len(0), _current_size(0),
- _rotate_size(0), _current_file(1), _file_count(0), _rotation_semaphore(1) {
+ _file_name(NULL), _archive_name(NULL), _archive_name_len(0),
+ _rotate_size(DefaultFileSize), _file_count(DefaultFileCount),
+ _current_size(0), _current_file(0), _rotation_semaphore(1) {
_file_name = make_file_name(name, _pid_str, _vm_start_time_str);
}
@@ -59,9 +60,6 @@
LogFileOutput::~LogFileOutput() {
if (_stream != NULL) {
- if (_archive_name != NULL) {
- archive();
- }
if (fclose(_stream) != 0) {
jio_fprintf(defaultStream::error_stream(), "Could not close log file '%s' (%s).\n",
_file_name, os::strerror(errno));
@@ -72,7 +70,7 @@
os::free(const_cast<char*>(_name));
}
-size_t LogFileOutput::parse_value(const char* value_str) {
+static size_t parse_value(const char* value_str) {
char* end;
unsigned long long value = strtoull(value_str, &end, 10);
if (!isdigit(*value_str) || end != value_str + strlen(value_str) || value >= SIZE_MAX) {
@@ -81,7 +79,80 @@
return value;
}
-bool LogFileOutput::configure_rotation(const char* options) {
+static bool file_exists(const char* filename) {
+ struct stat dummy_stat;
+ return os::stat(filename, &dummy_stat) == 0;
+}
+
+static uint number_of_digits(uint number) {
+ return number < 10 ? 1 : (number < 100 ? 2 : 3);
+}
+
+static bool is_regular_file(const char* filename) {
+ struct stat st;
+ int ret = os::stat(filename, &st);
+ if (ret != 0) {
+ return false;
+ }
+#ifdef _WINDOWS
+ return (st.st_mode & S_IFMT) == _S_IFREG;
+#else
+ return S_ISREG(st.st_mode);
+#endif
+}
+
+// Try to find the next number that should be used for file rotation.
+// Return UINT_MAX on error.
+static uint next_file_number(const char* filename,
+ uint number_of_digits,
+ uint filecount,
+ outputStream* errstream) {
+ bool found = false;
+ uint next_num = 0;
+
+ // len is filename + dot + digits + null char
+ size_t len = strlen(filename) + number_of_digits + 2;
+ char* archive_name = NEW_C_HEAP_ARRAY(char, len, mtLogging);
+ char* oldest_name = NEW_C_HEAP_ARRAY(char, len, mtLogging);
+
+ for (uint i = 0; i < filecount; i++) {
+ int ret = jio_snprintf(archive_name, len, "%s.%0*u",
+ filename, number_of_digits, i);
+ assert(ret > 0 && static_cast<size_t>(ret) == len - 1,
+ "incorrect buffer length calculation");
+
+ if (file_exists(archive_name) && !is_regular_file(archive_name)) {
+ // We've encountered something that's not a regular file among the
+ // possible file rotation targets. Fail immediately to prevent
+ // problems later.
+ errstream->print_cr("Possible rotation target file '%s' already exists "
+ "but is not a regular file.", archive_name);
+ next_num = UINT_MAX;
+ break;
+ }
+
+ // Stop looking if we find an unused file name
+ if (!file_exists(archive_name)) {
+ next_num = i;
+ found = true;
+ break;
+ }
+
+ // Keep track of oldest existing log file
+ if (!found
+ || os::compare_file_modified_times(oldest_name, archive_name) > 0) {
+ strcpy(oldest_name, archive_name);
+ next_num = i;
+ found = true;
+ }
+ }
+
+ FREE_C_HEAP_ARRAY(char, oldest_name);
+ FREE_C_HEAP_ARRAY(char, archive_name);
+ return next_num;
+}
+
+bool LogFileOutput::parse_options(const char* options, outputStream* errstream) {
if (options == NULL || strlen(options) == 0) {
return true;
}
@@ -107,22 +178,25 @@
if (strcmp(FileCountOptionKey, key) == 0) {
size_t value = parse_value(value_str);
- if (value == SIZE_MAX || value >= UINT_MAX) {
+ if (value > MaxRotationFileCount) {
+ errstream->print_cr("Invalid option: %s must be in range [0, %u]",
+ FileCountOptionKey,
+ MaxRotationFileCount);
success = false;
break;
}
_file_count = static_cast<uint>(value);
- _file_count_max_digits = static_cast<uint>(log10(static_cast<double>(_file_count)) + 1);
- _archive_name_len = 2 + strlen(_file_name) + _file_count_max_digits;
- _archive_name = NEW_C_HEAP_ARRAY(char, _archive_name_len, mtLogging);
} else if (strcmp(FileSizeOptionKey, key) == 0) {
size_t value = parse_value(value_str);
if (value == SIZE_MAX || value > SIZE_MAX / K) {
+ errstream->print_cr("Invalid option: %s must be in range [0, "
+ SIZE_FORMAT "]", FileSizeOptionKey, SIZE_MAX / K);
success = false;
break;
}
_rotate_size = value * K;
} else {
+ errstream->print_cr("Invalid option '%s' for log file output.", key);
success = false;
break;
}
@@ -133,15 +207,54 @@
return success;
}
-bool LogFileOutput::initialize(const char* options) {
- if (!configure_rotation(options)) {
+bool LogFileOutput::initialize(const char* options, outputStream* errstream) {
+ if (!parse_options(options, errstream)) {
return false;
}
+
+ if (_file_count > 0) {
+ // compute digits with filecount - 1 since numbers will start from 0
+ _file_count_max_digits = number_of_digits(_file_count - 1);
+ _archive_name_len = 2 + strlen(_file_name) + _file_count_max_digits;
+ _archive_name = NEW_C_HEAP_ARRAY(char, _archive_name_len, mtLogging);
+ }
+
+ log_trace(logging)("Initializing logging to file '%s' (filecount: %u"
+ ", filesize: " SIZE_FORMAT " KiB).",
+ _file_name, _file_count, _rotate_size / K);
+
+ if (_file_count > 0 && file_exists(_file_name)) {
+ if (!is_regular_file(_file_name)) {
+ errstream->print_cr("Unable to log to file %s with log file rotation: "
+ "%s is not a regular file",
+ _file_name, _file_name);
+ return false;
+ }
+ _current_file = next_file_number(_file_name,
+ _file_count_max_digits,
+ _file_count,
+ errstream);
+ if (_current_file == UINT_MAX) {
+ return false;
+ }
+ log_trace(logging)("Existing log file found, saving it as '%s.%0*u'",
+ _file_name, _file_count_max_digits, _current_file);
+ archive();
+ increment_file_count();
+ }
+
_stream = fopen(_file_name, FileOpenMode);
if (_stream == NULL) {
- log_error(logging)("Could not open log file '%s' (%s).\n", _file_name, os::strerror(errno));
+ errstream->print_cr("Error opening log file '%s': %s",
+ _file_name, strerror(errno));
return false;
}
+
+ if (_file_count == 0 && is_regular_file(_file_name)) {
+ log_trace(logging)("Truncating log file");
+ os::ftruncate(os::fileno(_stream), 0);
+ }
+
return true;
}
@@ -210,7 +323,7 @@
// Reset accumulated size, increase current file counter, and check for file count wrap-around.
_current_size = 0;
- _current_file = (_current_file >= _file_count ? 1 : _current_file + 1);
+ increment_file_count();
}
char* LogFileOutput::make_file_name(const char* file_name,
--- a/hotspot/src/share/vm/logging/logFileOutput.hpp Mon Apr 11 09:45:03 2016 +0200
+++ b/hotspot/src/share/vm/logging/logFileOutput.hpp Mon Apr 11 12:22:09 2016 +0200
@@ -39,8 +39,11 @@
static const char* PidFilenamePlaceholder;
static const char* TimestampFilenamePlaceholder;
static const char* TimestampFormat;
+ static const size_t DefaultFileCount = 5;
+ static const size_t DefaultFileSize = 20 * M;
static const size_t StartTimeBufferSize = 20;
- static const size_t PidBufferSize = 21;
+ static const size_t PidBufferSize = 21;
+ static const uint MaxRotationFileCount = 1000;
static char _pid_str[PidBufferSize];
static char _vm_start_time_str[StartTimeBufferSize];
@@ -61,18 +64,24 @@
void archive();
void rotate();
- bool configure_rotation(const char* options);
+ bool parse_options(const char* options, outputStream* errstream);
char *make_file_name(const char* file_name, const char* pid_string, const char* timestamp_string);
- static size_t parse_value(const char* value_str);
bool should_rotate() {
return _file_count > 0 && _rotate_size > 0 && _current_size >= _rotate_size;
}
+ void increment_file_count() {
+ _current_file++;
+ if (_current_file == _file_count) {
+ _current_file = 0;
+ }
+ }
+
public:
LogFileOutput(const char *name);
virtual ~LogFileOutput();
- virtual bool initialize(const char* options);
+ virtual bool initialize(const char* options, outputStream* errstream);
virtual int write(const LogDecorations& decorations, const char* msg);
virtual void force_rotate();
--- a/hotspot/src/share/vm/logging/logFileStreamOutput.hpp Mon Apr 11 09:45:03 2016 +0200
+++ b/hotspot/src/share/vm/logging/logFileStreamOutput.hpp Mon Apr 11 12:22:09 2016 +0200
@@ -53,7 +53,7 @@
LogStdoutOutput() : LogFileStreamOutput(stdout) {
set_config_string("all=off");
}
- virtual bool initialize(const char* options) {
+ virtual bool initialize(const char* options, outputStream* errstream) {
return false;
}
public:
@@ -69,7 +69,7 @@
LogStderrOutput() : LogFileStreamOutput(stderr) {
set_config_string("all=warning");
}
- virtual bool initialize(const char* options) {
+ virtual bool initialize(const char* options, outputStream* errstream) {
return false;
}
public:
--- a/hotspot/src/share/vm/logging/logOutput.hpp Mon Apr 11 09:45:03 2016 +0200
+++ b/hotspot/src/share/vm/logging/logOutput.hpp Mon Apr 11 12:22:09 2016 +0200
@@ -82,7 +82,7 @@
}
virtual const char* name() const = 0;
- virtual bool initialize(const char* options) = 0;
+ virtual bool initialize(const char* options, outputStream* errstream) = 0;
virtual int write(const LogDecorations &decorations, const char* msg) = 0;
};
--- a/hotspot/src/share/vm/runtime/os.hpp Mon Apr 11 09:45:03 2016 +0200
+++ b/hotspot/src/share/vm/runtime/os.hpp Mon Apr 11 12:22:09 2016 +0200
@@ -521,6 +521,9 @@
static int ftruncate(int fd, jlong length);
static int fsync(int fd);
static int available(int fd, jlong *bytes);
+ static int fileno(FILE* fp);
+
+ static int compare_file_modified_times(const char* file1, const char* file2);
//File i/o operations
--- a/hotspot/src/share/vm/utilities/internalVMTests.cpp Mon Apr 11 09:45:03 2016 +0200
+++ b/hotspot/src/share/vm/utilities/internalVMTests.cpp Mon Apr 11 12:22:09 2016 +0200
@@ -78,6 +78,9 @@
run_unit_test(Test_log_prefix);
run_unit_test(Test_log_big);
run_unit_test(Test_logtagset_duplicates);
+ run_unit_test(Test_log_file_startup_rotation);
+ run_unit_test(Test_log_file_startup_truncation);
+ run_unit_test(Test_invalid_log_file);
run_unit_test(DirectivesParser_test);
run_unit_test(Test_TempNewSymbol);
#if INCLUDE_VM_STRUCTS
--- a/hotspot/test/serviceability/logging/TestLogRotation.java Mon Apr 11 09:45:03 2016 +0200
+++ b/hotspot/test/serviceability/logging/TestLogRotation.java Mon Apr 11 12:22:09 2016 +0200
@@ -102,8 +102,10 @@
smallFilesNumber++;
}
}
- if (logs.length != numberOfFiles) {
- throw new Error("There are only " + logs.length + " logs instead " + numberOfFiles);
+ // Expect one more log file since the number-of-files doesn't include the active log file
+ int expectedNumberOfFiles = numberOfFiles + 1;
+ if (logs.length != expectedNumberOfFiles) {
+ throw new Error("There are " + logs.length + " logs instead of the expected " + expectedNumberOfFiles);
}
if (smallFilesNumber > 1) {
throw new Error("There should maximum one log with size < " + logFileSizeK + "K");
--- a/hotspot/test/serviceability/logging/TestQuotedLogOutputs.java Mon Apr 11 09:45:03 2016 +0200
+++ b/hotspot/test/serviceability/logging/TestQuotedLogOutputs.java Mon Apr 11 12:22:09 2016 +0200
@@ -101,7 +101,7 @@
output.shouldHaveExitValue(1);
// Ensure error message was logged
output.shouldMatch("([Mm]issing terminating quote)"
- + "|(Could not open log file '')"
+ + "|(Error opening log file '')"
+ "|(Output name can not be partially quoted)");
}
}