Added fixed log name support, take 2 (#489)

* 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.

* Ifdef away fcntl on mingw

* Use the defined HAVE_FCNTL instead

* ifdef away tests as well

add have_sys_wait for wait() on mingw.

* OS_WINDOWS bug in fseeking to the end, only triggered here

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)

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

src/config.h.cmake.in

@@ -112,6 +112,9 @@
 /* Define to 1 if you have the <sys/utsname.h> header file. */
 #cmakedefine HAVE_SYS_UTSNAME_H
 
+/* Define to 1 if you have the <sys/wait.h> header file. */
+#cmakedefine HAVE_SYS_WAIT_H
+
 /* Define to 1 if you have the <ucontext.h> header file. */
 #cmakedefine HAVE_UCONTEXT_H
 

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);
 

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,23 +995,64 @@ 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);
+
+  // 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.
+  // TODO windows implementation of this (as flock is not available on mingw).
+  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;
+  }
 #endif
 
+  //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;
   }
-
+#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 <program_name>.<severity>,
   // 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

src/logging_unittest.cc

@@ -40,9 +40,13 @@
 #ifdef HAVE_UNISTD_H
 # include <unistd.h>
 #endif
+#ifdef HAVE_SYS_WAIT_H
+# include <sys/wait.h>
+#endif
 
 #include <iomanip>
 #include <iostream>
+#include <fstream>
 #include <memory>
 #include <queue>
 #include <sstream>
@@ -103,6 +107,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 +182,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 +234,8 @@ int main(int argc, char **argv) {
   FLAGS_logtostderr = false;
 
   TestBasename();
+  TestBasenameAppendWhenNoTimestamp();
+  TestTwoProcessesWrite();
   TestSymlink();
   TestExtension();
   TestWrapper();
@@ -666,7 +675,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<string> files;
   GetFiles(name + "*", &files);
   CHECK_EQ(files.size(), 1UL);
@@ -675,13 +685,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 +713,65 @@ 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();
+
+  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";
+  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() {
+// 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 + "*");
+
+  //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 + "*");
+#endif
+}
+
 static void TestSymlink() {
 #ifndef OS_WINDOWS
   fprintf(stderr, "==== Test setting log file symlink\n");