From c1d90644e804cad8a2bddc7ea13ea91df28adf85 Mon Sep 17 00:00:00 2001 From: Ezequiel Lara Gomez Date: Mon, 4 Nov 2019 12:59:15 +0000 Subject: [PATCH 1/5] Added fixed log name support, take 2 See https://code.google.com/p/google-glog/issues/detail?id=209 and former https://github.com/google/glog/pull/19 - this is an updated version of that patch. It adds a flag that allows to switch behavior from base_filename + filename_extension + time_pid_string to base_filename + filename_extension, while still defaulting to the current behavior to avoid breakage in existing code. This change would allow easier log rotation schemes and better control on what's written on disk. --- Makefile.am | 4 +-- src/glog/logging.h.in | 3 ++ src/logging.cc | 45 +++++++++++++++++++++++--- src/logging_unittest.cc | 71 +++++++++++++++++++++++++++++++++++++++-- 4 files changed, 113 insertions(+), 10 deletions(-) diff --git a/Makefile.am b/Makefile.am index d5644a2f9..e792332a0 100644 --- a/Makefile.am +++ b/Makefile.am @@ -208,9 +208,9 @@ libglog_la_SOURCES = $(gloginclude_HEADERS) \ src/base/commandlineflags.h src/googletest.h nodist_libglog_la_SOURCES = $(nodist_gloginclude_HEADERS) -libglog_la_CXXFLAGS = $(PTRHEAD_CFLAGS) $(GFLAGS_CFLAGS) $(MINGW_CFLAGS) \ +libglog_la_CXXFLAGS = $(PTHREAD_CFLAGS) $(GFLAGS_CFLAGS) $(MINGW_CFLAGS) \ $(AM_CXXFLAGS) -DNDEBUG -libglog_la_LDFLAGS = $(PTRHEAD_CFLAGS) $(GFLAGS_LDFLAGS) +libglog_la_LDFLAGS = $(PTHREAD_CFLAGS) $(GFLAGS_LDFLAGS) libglog_la_LIBADD = $(COMMON_LIBS) ## The location of the windows project file for each binary we make diff --git a/src/glog/logging.h.in b/src/glog/logging.h.in index 0ec46a167..64bed1a90 100644 --- a/src/glog/logging.h.in +++ b/src/glog/logging.h.in @@ -330,6 +330,9 @@ typedef unsigned __int64 uint64; using fLS::FLAGS_##name #endif +// Set whether appending a timestamp to the log file name +DECLARE_bool(timestamp_in_logfile_name); + // Set whether log messages go to stderr instead of logfiles DECLARE_bool(logtostderr); diff --git a/src/logging.cc b/src/logging.cc index a9a9e82e9..cde566e42 100644 --- a/src/logging.cc +++ b/src/logging.cc @@ -109,6 +109,9 @@ static bool BoolFromEnv(const char *varname, bool defval) { return memchr("tTyY1\0", valstr[0], 6) != NULL; } +GLOG_DEFINE_bool(timestamp_in_logfile_name, + BoolFromEnv("GOOGLE_TIMESTAMP_IN_LOGFILE_NAME", true), + "put a timestamp at the end of the log file name"); GLOG_DEFINE_bool(logtostderr, BoolFromEnv("GOOGLE_LOGTOSTDERR", false), "log messages go to stderr instead of logfiles"); GLOG_DEFINE_bool(alsologtostderr, BoolFromEnv("GOOGLE_ALSOLOGTOSTDERR", false), @@ -449,7 +452,7 @@ class LogFileObject : public base::Logger { int64 next_flush_time_; // cycle count at which to flush log // Actually create a logfile using the value of base_filename_ and the - // supplied argument time_pid_string + // optional argument time_pid_string // REQUIRES: lock_ is held bool CreateLogfile(const string& time_pid_string); }; @@ -992,20 +995,52 @@ void LogFileObject::FlushUnlocked(){ } bool LogFileObject::CreateLogfile(const string& time_pid_string) { - string string_filename = base_filename_+filename_extension_+ - time_pid_string; + string string_filename = base_filename_+filename_extension_; + if (FLAGS_timestamp_in_logfile_name) { + string_filename += time_pid_string; + } const char* filename = string_filename.c_str(); - int fd = open(filename, O_WRONLY | O_CREAT | O_EXCL, FLAGS_logfile_mode); + //only write to files, create if non-existant. + int flags = O_WRONLY | O_CREAT; + if (FLAGS_timestamp_in_logfile_name) { + //demand that the file is unique for our timestamp (fail if it exists). + flags = flags | O_EXCL; + } + int fd = open(filename, flags, FLAGS_logfile_mode); if (fd == -1) return false; #ifdef HAVE_FCNTL // Mark the file close-on-exec. We don't really care if this fails fcntl(fd, F_SETFD, FD_CLOEXEC); #endif + // Mark the file as exclusive write access to avoid two clients logging to the + // same file. This applies particularly when !FLAGS_timestamp_in_logfile_name + // (otherwise open would fail because the O_EXCL flag on similar filename). + // locks are released on unlock or close() automatically, only after log is + // released. + // This will work after a fork as it is not inherited (not stored in the fd). + // Lock will not be lost because the file is opened with exclusive lock (write) + // and we will never read from it inside the process. + static struct flock w_lock; + + w_lock.l_type = F_WRLCK; + w_lock.l_start = 0; + w_lock.l_whence = SEEK_SET; + w_lock.l_len = 0; + + int wlock_ret = fcntl(fd, F_SETLK, &w_lock); + if (wlock_ret == -1) { + close(fd); //as we are failing already, do not check errors here + return false; + } + + //fdopen in append mode so if the file exists it will fseek to the end file_ = fdopen(fd, "a"); // Make a FILE*. if (file_ == NULL) { // Man, we're screwed! close(fd); - unlink(filename); // Erase the half-baked evidence: an unusable log file + if (FLAGS_timestamp_in_logfile_name) { + unlink(filename); // Erase the half-baked evidence: an unusable log file, only if we just created it. + } return false; } diff --git a/src/logging_unittest.cc b/src/logging_unittest.cc index c9d210cc5..33bb8dd1b 100644 --- a/src/logging_unittest.cc +++ b/src/logging_unittest.cc @@ -40,9 +40,11 @@ #ifdef HAVE_UNISTD_H # include #endif +#include #include #include +#include #include #include #include @@ -103,6 +105,8 @@ static void TestCHECK(); static void TestDCHECK(); static void TestSTREQ(); static void TestBasename(); +static void TestBasenameAppendWhenNoTimestamp(); +static void TestTwoProcessesWrite(); static void TestSymlink(); static void TestExtension(); static void TestWrapper(); @@ -176,6 +180,7 @@ BENCHMARK(BM_vlog); int main(int argc, char **argv) { FLAGS_colorlogtostderr = false; + FLAGS_timestamp_in_logfile_name = true; #ifdef HAVE_LIB_GFLAGS ParseCommandLineFlags(&argc, &argv, true); #endif @@ -227,6 +232,8 @@ int main(int argc, char **argv) { FLAGS_logtostderr = false; TestBasename(); + TestBasenameAppendWhenNoTimestamp(); + TestTwoProcessesWrite(); TestSymlink(); TestExtension(); TestWrapper(); @@ -666,7 +673,8 @@ static void DeleteFiles(const string& pattern) { } } -static void CheckFile(const string& name, const string& expected_string) { +//check string is in file (or is *NOT*, depending on optional checkInFileOrNot) +static void CheckFile(const string& name, const string& expected_string, const bool checkInFileOrNot = true) { vector files; GetFiles(name + "*", &files); CHECK_EQ(files.size(), 1UL); @@ -675,13 +683,16 @@ static void CheckFile(const string& name, const string& expected_string) { CHECK(file != NULL) << ": could not open " << files[0]; char buf[1000]; while (fgets(buf, sizeof(buf), file) != NULL) { - if (strstr(buf, expected_string.c_str()) != NULL) { + char* first = strstr(buf, expected_string.c_str()); + //if first == NULL, not found. + //Terser than if (checkInFileOrNot && first != NULL || !check... + if (checkInFileOrNot != (first == NULL)) { fclose(file); return; } } fclose(file); - LOG(FATAL) << "Did not find " << expected_string << " in " << files[0]; + LOG(FATAL) << "Did " << (checkInFileOrNot? "" : "not ") << " find " << expected_string << " in " << files[0]; } static void TestBasename() { @@ -700,6 +711,60 @@ static void TestBasename() { DeleteFiles(dest + "*"); } +static void TestBasenameAppendWhenNoTimestamp() { + fprintf(stderr, "==== Test setting log file basename without timestamp and appending properly\n"); + const string dest = FLAGS_test_tmpdir + "/logging_test_basename_append_when_no_timestamp"; + DeleteFiles(dest + "*"); + + ofstream out(dest.c_str()); + out << "test preexisting content" << endl; + out.close(); + + FLAGS_timestamp_in_logfile_name=false; + SetLogDestination(GLOG_INFO, dest.c_str()); + LOG(INFO) << "message to new base, appending to preexisting file"; + FlushLogFiles(GLOG_INFO); + FLAGS_timestamp_in_logfile_name=true; + + //if the logging overwrites the file instead of appending it will fail. + CheckFile(dest, "test preexisting content"); + CheckFile(dest, "message to new base, appending to preexisting file"); + + // Release file handle for the destination file to unlock the file in Windows. + LogToStderr(); + DeleteFiles(dest + "*"); +} + +static void TestTwoProcessesWrite() { + fprintf(stderr, "==== Test setting log file basename and two processes writing - second should fail\n"); + const string dest = FLAGS_test_tmpdir + "/logging_test_basename_two_processes_writing"; + DeleteFiles(dest + "*"); + + //make both processes write into the same file (easier test) + FLAGS_timestamp_in_logfile_name=false; + SetLogDestination(GLOG_INFO, dest.c_str()); + LOG(INFO) << "message to new base, parent"; + FlushLogFiles(GLOG_INFO); + + pid_t pid = fork(); + CHECK_ERR(pid); + if (pid == 0) { + LOG(INFO) << "message to new base, child - should only appear on STDERR not on the file"; + ShutdownGoogleLogging(); //for children proc + exit(0); + } else if (pid > 0) { + wait(NULL); + } + FLAGS_timestamp_in_logfile_name=true; + + CheckFile(dest, "message to new base, parent"); + CheckFile(dest, "message to new base, child - should only appear on STDERR not on the file", false); + + // Release + LogToStderr(); + DeleteFiles(dest + "*"); +} + static void TestSymlink() { #ifndef OS_WINDOWS fprintf(stderr, "==== Test setting log file symlink\n"); From f4e59ba63fa518fc5aa3922c592732a8f34bc659 Mon Sep 17 00:00:00 2001 From: Ezequiel Lara Gomez Date: Mon, 4 Nov 2019 14:29:14 +0000 Subject: [PATCH 2/5] Ifdef away fcntl on mingw --- src/logging.cc | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/logging.cc b/src/logging.cc index cde566e42..907f57ad3 100644 --- a/src/logging.cc +++ b/src/logging.cc @@ -1013,6 +1013,7 @@ bool LogFileObject::CreateLogfile(const string& time_pid_string) { fcntl(fd, F_SETFD, FD_CLOEXEC); #endif +#ifdef _struct_flock // Mark the file as exclusive write access to avoid two clients logging to the // same file. This applies particularly when !FLAGS_timestamp_in_logfile_name // (otherwise open would fail because the O_EXCL flag on similar filename). @@ -1033,6 +1034,7 @@ bool LogFileObject::CreateLogfile(const string& time_pid_string) { close(fd); //as we are failing already, do not check errors here return false; } +#endif //fdopen in append mode so if the file exists it will fseek to the end file_ = fdopen(fd, "a"); // Make a FILE*. From 73bc3f07d1d87249528e794ab17636482ea23145 Mon Sep 17 00:00:00 2001 From: Ezequiel Lara Gomez Date: Mon, 4 Nov 2019 17:34:13 +0000 Subject: [PATCH 3/5] Use the defined HAVE_FCNTL instead --- src/logging.cc | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/src/logging.cc b/src/logging.cc index 907f57ad3..ced03542b 100644 --- a/src/logging.cc +++ b/src/logging.cc @@ -1011,9 +1011,7 @@ bool LogFileObject::CreateLogfile(const string& time_pid_string) { #ifdef HAVE_FCNTL // Mark the file close-on-exec. We don't really care if this fails fcntl(fd, F_SETFD, FD_CLOEXEC); -#endif -#ifdef _struct_flock // Mark the file as exclusive write access to avoid two clients logging to the // same file. This applies particularly when !FLAGS_timestamp_in_logfile_name // (otherwise open would fail because the O_EXCL flag on similar filename). @@ -1022,6 +1020,7 @@ bool LogFileObject::CreateLogfile(const string& time_pid_string) { // This will work after a fork as it is not inherited (not stored in the fd). // Lock will not be lost because the file is opened with exclusive lock (write) // and we will never read from it inside the process. + // TBD windows version of this. static struct flock w_lock; w_lock.l_type = F_WRLCK; From d179577f154c9c9e67529f3e8c159f394dfe9f15 Mon Sep 17 00:00:00 2001 From: Ezequiel Lara Gomez Date: Tue, 5 Nov 2019 12:31:45 +0000 Subject: [PATCH 4/5] ifdef away tests as well add have_sys_wait for wait() on mingw. --- CMakeLists.txt | 1 + src/config.h.cmake.in | 3 +++ src/logging_unittest.cc | 7 ++++++- 3 files changed, 10 insertions(+), 1 deletion(-) diff --git a/CMakeLists.txt b/CMakeLists.txt index 4f64b411e..cdc34eeda 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -77,6 +77,7 @@ check_include_file (sys/syscall.h HAVE_SYS_SYSCALL_H) check_include_file (sys/time.h HAVE_SYS_TIME_H) check_include_file (sys/types.h HAVE_SYS_TYPES_H) check_include_file (sys/utsname.h HAVE_SYS_UTSNAME_H) +check_include_file (sys/wait.h HAVE_SYS_WAIT_H) check_include_file (syscall.h HAVE_SYSCALL_H) check_include_file (syslog.h HAVE_SYSLOG_H) check_include_file (ucontext.h HAVE_UCONTEXT_H) diff --git a/src/config.h.cmake.in b/src/config.h.cmake.in index ee8cdfe22..f038de2cc 100644 --- a/src/config.h.cmake.in +++ b/src/config.h.cmake.in @@ -112,6 +112,9 @@ /* Define to 1 if you have the header file. */ #cmakedefine HAVE_SYS_UTSNAME_H +/* Define to 1 if you have the header file. */ +#cmakedefine HAVE_SYS_WAIT_H + /* Define to 1 if you have the header file. */ #cmakedefine HAVE_UCONTEXT_H diff --git a/src/logging_unittest.cc b/src/logging_unittest.cc index 33bb8dd1b..ab872e6df 100644 --- a/src/logging_unittest.cc +++ b/src/logging_unittest.cc @@ -40,7 +40,9 @@ #ifdef HAVE_UNISTD_H # include #endif -#include +#ifdef HAVE_SYS_WAIT_H +# include +#endif #include #include @@ -736,6 +738,8 @@ static void TestBasenameAppendWhenNoTimestamp() { } static void TestTwoProcessesWrite() { +// test only implemented for platforms with fork & wait; the actual implementation relies on flock +#if defined(HAVE_SYS_WAIT_H) && defined(HAVE_UNISTD_H) && defined(HAVE_FCNTL) fprintf(stderr, "==== Test setting log file basename and two processes writing - second should fail\n"); const string dest = FLAGS_test_tmpdir + "/logging_test_basename_two_processes_writing"; DeleteFiles(dest + "*"); @@ -763,6 +767,7 @@ static void TestTwoProcessesWrite() { // Release LogToStderr(); DeleteFiles(dest + "*"); +#endif } static void TestSymlink() { From 422cd62a6d4c08ea214621efee0c7304a5f8732f Mon Sep 17 00:00:00 2001 From: Ezequiel Lara Gomez Date: Tue, 5 Nov 2019 16:45:28 +0000 Subject: [PATCH 5/5] OS_WINDOWS bug in fseeking to the end, only triggered here --- src/logging.cc | 12 ++++++++++-- src/logging_unittest.cc | 4 +++- 2 files changed, 13 insertions(+), 3 deletions(-) diff --git a/src/logging.cc b/src/logging.cc index ced03542b..42cfd01ec 100644 --- a/src/logging.cc +++ b/src/logging.cc @@ -1020,7 +1020,7 @@ bool LogFileObject::CreateLogfile(const string& time_pid_string) { // This will work after a fork as it is not inherited (not stored in the fd). // Lock will not be lost because the file is opened with exclusive lock (write) // and we will never read from it inside the process. - // TBD windows version of this. + // TODO windows implementation of this (as flock is not available on mingw). static struct flock w_lock; w_lock.l_type = F_WRLCK; @@ -1044,7 +1044,15 @@ bool LogFileObject::CreateLogfile(const string& time_pid_string) { } return false; } - +#ifdef OS_WINDOWS + // https://github.com/golang/go/issues/27638 - make sure we seek to the end to append + // empirically replicated with wine over mingw build + if (!FLAGS_timestamp_in_logfile_name) { + if (fseek(file_, 0, SEEK_END) != 0) { + return false; + } + } +#endif // We try to create a symlink called ., // which is easier to use. (Every time we create a new logfile, // we destroy the old symlink and create a new one, so it always diff --git a/src/logging_unittest.cc b/src/logging_unittest.cc index ab872e6df..a98067712 100644 --- a/src/logging_unittest.cc +++ b/src/logging_unittest.cc @@ -694,7 +694,7 @@ static void CheckFile(const string& name, const string& expected_string, const b } } fclose(file); - LOG(FATAL) << "Did " << (checkInFileOrNot? "" : "not ") << " find " << expected_string << " in " << files[0]; + LOG(FATAL) << "Did " << (checkInFileOrNot? "not " : "") << "find " << expected_string << " in " << files[0]; } static void TestBasename() { @@ -722,6 +722,8 @@ static void TestBasenameAppendWhenNoTimestamp() { out << "test preexisting content" << endl; out.close(); + CheckFile(dest, "test preexisting content"); + FLAGS_timestamp_in_logfile_name=false; SetLogDestination(GLOG_INFO, dest.c_str()); LOG(INFO) << "message to new base, appending to preexisting file";