Add Header to logging to capture application level information

Summary:
This change adds LogHeader provision to the logger. For the rolling logger
implementation, the headers are copied over to the new log file every time
there is a log roll over.

Test Plan: Added a unit test to test the rolling log case.

Reviewers: sdong

Subscribers: dhruba

Differential Revision: https://reviews.facebook.net/D32817

include/rocksdb/env.h

@@ -617,6 +617,15 @@ class Logger {
       : log_level_(log_level) {}
   virtual ~Logger();
 
+  // Write a header to the log file with the specified format
+  // It is recommended that you log all header information at the start of the
+  // application. But it is not enforced.
+  virtual void LogHeader(const char* format, va_list ap) {
+    // Default implementation does a simple INFO level log write.
+    // Please override as per the logger class requirement.
+    Logv(format, ap);
+  }
+
   // Write an entry to the log file with the specified format.
   virtual void Logv(const char* format, va_list ap) = 0;
 
@@ -678,6 +687,7 @@ extern void Log(const InfoLogLevel log_level,
                 const shared_ptr<Logger>& info_log, const char* format, ...);
 
 // a set of log functions with different log levels.
+extern void Header(const shared_ptr<Logger>& info_log, const char* format, ...);
 extern void Debug(const shared_ptr<Logger>& info_log, const char* format, ...);
 extern void Info(const shared_ptr<Logger>& info_log, const char* format, ...);
 extern void Warn(const shared_ptr<Logger>& info_log, const char* format, ...);
@@ -705,6 +715,7 @@ extern void Log(Logger* info_log, const char* format, ...)
     ;
 
 // a set of log functions with different log levels.
+extern void Header(Logger* info_log, const char* format, ...);
 extern void Debug(Logger* info_log, const char* format, ...);
 extern void Info(Logger* info_log, const char* format, ...);
 extern void Warn(Logger* info_log, const char* format, ...);

util/auto_roll_logger.cc

@@ -37,6 +37,27 @@ void AutoRollLogger::RollLogFile() {
   env_->RenameFile(log_fname_, old_fname);
 }
 
+string AutoRollLogger::ValistToString(const char* format, va_list args) const {
+  // Any log messages longer than 1024 will get truncated.
+  // The user is responsible for chopping longer messages into multi line log
+  static const int MAXBUFFERSIZE = 1024;
+  char buffer[MAXBUFFERSIZE];
+
+  int count = vsnprintf(buffer, MAXBUFFERSIZE, format, args);
+  (void) count;
+  assert(count >= 0);
+
+  return buffer;
+}
+
+void AutoRollLogger::LogInternal(const char* format, ...) {
+  mutex_.AssertHeld();
+  va_list args;
+  va_start(args, format);
+  logger_->Logv(format, args);
+  va_end(args);
+}
+
 void AutoRollLogger::Logv(const char* format, va_list ap) {
   assert(GetStatus().ok());
 
@@ -51,6 +72,8 @@ void AutoRollLogger::Logv(const char* format, va_list ap) {
         // can't really log the error if creating a new LOG file failed
         return;
       }
+
+      WriteHeaderInfo();
     }
 
     // pin down the current logger_ instance before releasing the mutex.
@@ -66,6 +89,29 @@ void AutoRollLogger::Logv(const char* format, va_list ap) {
   logger->Logv(format, ap);
 }
 
+void AutoRollLogger::WriteHeaderInfo() {
+  mutex_.AssertHeld();
+  for (auto header : headers_) {
+    LogInternal("%s", header.c_str());
+  }
+}
+
+void AutoRollLogger::LogHeader(const char* format, va_list args) {
+  // header message are to be retained in memory. Since we cannot make any
+  // assumptions about the data contained in va_list, we will retain them as
+  // strings
+  va_list tmp;
+  va_copy(tmp, args);
+  string data = ValistToString(format, tmp);
+  va_end(tmp);
+
+  MutexLock l(&mutex_);
+  headers_.push_back(data);
+
+  // Log the original message to the current log
+  logger_->Logv(format, args);
+}
+
 bool AutoRollLogger::LogExpired() {
   if (cached_now_access_count >= call_NowMicros_every_N_records_) {
     cached_now = static_cast<uint64_t>(env_->NowMicros() * 1e-6);

util/auto_roll_logger.h

@@ -7,6 +7,8 @@
 // where enough posix functionality is available.
 
 #pragma once
+#include <list>
+
 #include "db/filename.h"
 #include "port/port.h"
 #include "util/posix_logger.h"
@@ -40,6 +42,10 @@ class AutoRollLogger : public Logger {
 
   void Logv(const char* format, va_list ap);
 
+  // Write a header entry to the log. All header information will be written
+  // again every time the log rolls over.
+  virtual void LogHeader(const char* format, va_list ap) override;
+
   // check if the logger has encountered any problem.
   Status GetStatus() {
     return status_;
@@ -57,10 +63,15 @@ class AutoRollLogger : public Logger {
   }
 
  private:
-
   bool LogExpired();
   Status ResetLogger();
   void RollLogFile();
+  // Log message to logger without rolling
+  void LogInternal(const char* format, ...);
+  // Serialize the va_list to a string
+  std::string ValistToString(const char* format, va_list args) const;
+  // Write the logs marked as headers to the new log file
+  void WriteHeaderInfo();
 
   std::string log_fname_; // Current active info log's file name.
   std::string dbname_;
@@ -72,6 +83,8 @@ class AutoRollLogger : public Logger {
   Status status_;
   const size_t kMaxLogFileSize;
   const size_t kLogFileTimeToRoll;
+  // header information
+  std::list<std::string> headers_;
   // to avoid frequent env->NowMicros() calls, we cached the current time
   uint64_t cached_now;
   uint64_t ctime_;

util/auto_roll_logger_test.cc

@@ -285,6 +285,47 @@ TEST(AutoRollLoggerTest, InfoLogLevel) {
   inFile.close();
 }
 
+// Test the logger Header function for roll over logs
+// We expect the new logs creates as roll over to carry the headers specified
+TEST(AutoRollLoggerTest, LogHeaderTest) {
+  static const size_t MAX_HEADERS = 10;
+  static const size_t LOG_MAX_SIZE = 1024 * 5;
+  static const std::string HEADER_STR = "Log header line";
+
+  InitTestDb();
+
+  AutoRollLogger logger(Env::Default(), kTestDir, /*db_log_dir=*/ "",
+                        LOG_MAX_SIZE, /*log_file_time_to_roll=*/ 0);
+
+  // log some headers
+  for (size_t i = 0; i < MAX_HEADERS; i++) {
+    Header(&logger, "%s %d", HEADER_STR.c_str(), i);
+  }
+
+  // log enough data to cause a roll over
+  size_t i = 0;
+  while (logger.GetLogFileSize() < LOG_MAX_SIZE) {
+    Info(&logger, (kSampleMessage + ":LogHeaderTest line %d").c_str(), i);
+    ++i;
+  }
+
+  // verify that the new log contains all the header logs
+  std::stringstream ssbuf;
+  std::string line;
+  size_t count = 0;
+
+  std::ifstream inFile(AutoRollLoggerTest::kLogFile.c_str());
+  ssbuf << inFile.rdbuf();
+
+  while (getline(ssbuf, line)) {
+    if (line.find(HEADER_STR) != std::string::npos) {
+      count++;
+    }
+  }
+
+  ASSERT_EQ(count, MAX_HEADERS);
+}
+
 TEST(AutoRollLoggerTest, LogFileExistence) {
   rocksdb::DB* db;
   rocksdb::Options options;

util/env.cc

@@ -59,6 +59,15 @@ void Log(const InfoLogLevel log_level, Logger* info_log, const char* format,
   }
 }
 
+void Header(Logger* info_log, const char* format, ...) {
+  if (info_log) {
+    va_list ap;
+    va_start(ap, format);
+    info_log->LogHeader(format, ap);
+    va_end(ap);
+  }
+}
+
 void Debug(Logger* info_log, const char* format, ...) {
   if (info_log && info_log->GetInfoLogLevel() <= InfoLogLevel::DEBUG_LEVEL) {
     va_list ap;
@@ -118,6 +127,15 @@ void Log(const InfoLogLevel log_level, const shared_ptr<Logger>& info_log,
   }
 }
 
+void Header(const shared_ptr<Logger>& info_log, const char* format, ...) {
+  if (info_log) {
+    va_list ap;
+    va_start(ap, format);
+    info_log->LogHeader(format, ap);
+    va_end(ap);
+  }
+}
+
 void Debug(const shared_ptr<Logger>& info_log, const char* format, ...) {
   if (info_log) {
     va_list ap;