# HG changeset patch # User mlarsson # Date 1460370129 -7200 # Node ID 1d5551f466ee5cc87cee05594435b354fbbd77e3 # Parent 5373bbadb43365984126ec419ef386d5da06f846 8146879: Add option for handling existing log files in UL Reviewed-by: dsamersoff, gziemski, rehn diff -r 5373bbadb433 -r 1d5551f466ee hotspot/src/os/bsd/vm/os_bsd.cpp --- 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; } diff -r 5373bbadb433 -r 1d5551f466ee hotspot/src/os/linux/vm/os_linux.cpp --- 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 /////////////// diff -r 5373bbadb433 -r 1d5551f466ee hotspot/src/os/posix/vm/os_posix.cpp --- 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]; diff -r 5373bbadb433 -r 1d5551f466ee hotspot/src/os/solaris/vm/os_solaris.cpp --- 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) { diff -r 5373bbadb433 -r 1d5551f466ee hotspot/src/os/windows/vm/os_windows.cpp --- 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 diff -r 5373bbadb433 -r 1d5551f466ee hotspot/src/share/vm/logging/log.cpp --- 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 diff -r 5373bbadb433 -r 1d5551f466ee hotspot/src/share/vm/logging/logConfiguration.cpp --- 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; diff -r 5373bbadb433 -r 1d5551f466ee hotspot/src/share/vm/logging/logFileOutput.cpp --- 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(_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(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(value); - _file_count_max_digits = static_cast(log10(static_cast(_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, diff -r 5373bbadb433 -r 1d5551f466ee hotspot/src/share/vm/logging/logFileOutput.hpp --- 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(); diff -r 5373bbadb433 -r 1d5551f466ee hotspot/src/share/vm/logging/logFileStreamOutput.hpp --- 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: diff -r 5373bbadb433 -r 1d5551f466ee hotspot/src/share/vm/logging/logOutput.hpp --- 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; }; diff -r 5373bbadb433 -r 1d5551f466ee hotspot/src/share/vm/runtime/os.hpp --- 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 diff -r 5373bbadb433 -r 1d5551f466ee hotspot/src/share/vm/utilities/internalVMTests.cpp --- 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 diff -r 5373bbadb433 -r 1d5551f466ee hotspot/test/serviceability/logging/TestLogRotation.java --- 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"); diff -r 5373bbadb433 -r 1d5551f466ee hotspot/test/serviceability/logging/TestQuotedLogOutputs.java --- 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)"); } }