cta/CTA#106 cta-taped logging a timestamp

All sub-classes of the Logger class, excluding DummyLogger and
SysLogLogger, now prefix each log message with the same header
as CASTOR.

Please note that SysLogLogger class intentionally leaves the
creation of log message headers to rsyslog.  It is the
responsibility of the system administrator/operator to configure
rsyslog to generate the header syntax they wish including the
precision of the timestamp within the header.

common/log/DummyLogger.cpp

@@ -42,7 +42,9 @@ void DummyLogger::prepareForFork() {}
 //------------------------------------------------------------------------------
 // writeMsgToUnderlyingLoggingSystem
 //------------------------------------------------------------------------------
-void DummyLogger::writeMsgToUnderlyingLoggingSystem(const std::string &msg) {}
+void DummyLogger::writeMsgToUnderlyingLoggingSystem(const std::string &header, const std::string &body) {
+  // Do nothing
+}
 
 } // namespace log
 } // namespace cta

common/log/DummyLogger.hpp

@@ -59,14 +59,21 @@ public:
 protected:
 
   /**
-   * Writes the specified log message to the underlying logging system.
+   * Writes the specified msg to the underlying logging system.
    *
    * This method is to be implemented by concrete sub-classes of the Logger
    * class.
    *
-   * @param msg The message to be logged.
+   * Please note it is the responsibility of a concrete sub-class to decide
+   * whether or not to use the specified log message header.  For example, the
+   * SysLogLogger sub-class does not use the header.  Instead it relies on
+   * rsyslog to provide a header.
+   *
+   * @param header The header of the message to be logged.  It is the
+   * esponsibility of the concrete sub-class
+   * @param body The body of the message to be logged.
    */
-  void writeMsgToUnderlyingLoggingSystem(const std::string &msg) override;
+  void writeMsgToUnderlyingLoggingSystem(const std::string &header, const std::string &body) override;
 
 }; // class DummyLogger
 

common/log/FileLogger.cpp

@@ -56,11 +56,14 @@ void FileLogger::prepareForFork() {
 //-----------------------------------------------------------------------------
 // writeMsgToUnderlyingLoggingSystem
 //-----------------------------------------------------------------------------
-void FileLogger::writeMsgToUnderlyingLoggingSystem(const std::string &msg) {
+void FileLogger::writeMsgToUnderlyingLoggingSystem(const std::string &header, const std::string &body) {
   if (-1 == m_fd)
     throw cta::exception::Exception("In FileLogger::writeMsgToUnderlyingLoggingSystem(): file is not properly initialized");
+
+  const std::string headerPlusBody = header + body;
+
   // Prepare the string to print (for size)
-  std::string m = msg.substr(0, m_maxMsgLen) + "\n";
+  std::string m = headerPlusBody.substr(0, m_maxMsgLen) + "\n";
   
   // enter critical section
   threading::MutexLocker lock(m_mutex);
@@ -71,4 +74,4 @@ void FileLogger::writeMsgToUnderlyingLoggingSystem(const std::string &msg) {
 }
 
 } // namespace log
-} // namespace cta
\ No newline at end of file
+} // namespace cta

common/log/FileLogger.hpp

@@ -68,14 +68,21 @@ protected:
   int m_fd=-1;
 
   /**
-   * Writes the specified log message to the underlying logging system.
+   * Writes the specified msg to the underlying logging system.
    *
    * This method is to be implemented by concrete sub-classes of the Logger
    * class.
    *
-   * @param msg The message to be logged.
+   * Please note it is the responsibility of a concrete sub-class to decide
+   * whether or not to use the specified log message header.  For example, the
+   * SysLogLogger sub-class does not use the header.  Instead it relies on
+   * rsyslog to provide a header.
+   *
+   * @param header The header of the message to be logged.  It is the
+   * esponsibility of the concrete sub-class
+   * @param body The body of the message to be logged.
    */
-  void writeMsgToUnderlyingLoggingSystem(const std::string &msg) override;
+  void writeMsgToUnderlyingLoggingSystem(const std::string &header, const std::string &body) override;
 
 }; // class StringLogger
 

common/log/Logger.cpp

@@ -57,16 +57,10 @@ void Logger::operator() (
   const std::list<Param> &params) {
 
   const std::string rawParams;
+  struct timeval timeStamp;
+  gettimeofday(&timeStamp, NULL);
   const int pid = getpid();
 
-  //-------------------------------------------------------------------------
-  // Note that we do here part of the work of the real syslog call, by
-  // building the message ourselves. We then only call a reduced version of
-  // syslog (namely writeMsgToUnderlyingLoggingSystem). The reason behind it is to be able to set
-  // the message timestamp ourselves, in case we log messages asynchronously,
-  // as we do when retrieving logs from the DB
-  //-------------------------------------------------------------------------
-
   // Ignore messages whose priority is not of interest
   if(priority > m_logMask) {
     return;
@@ -84,59 +78,10 @@ void Logger::operator() (
   // Safe to get a reference to the textual representation of the priority
   const std::string &priorityText = priorityTextPair->second;
 
-  std::ostringstream os;
+  const std::string header = createMsgHeader(priority | LOG_LOCAL3, timeStamp, m_programName, pid);
+  const std::string body = createMsgBody(priority, priorityText, msg, params, rawParams, m_programName, pid);
 
-  writeLogMsg(
-    os,
-    priority,
-    priorityText,
-    msg,
-    params,
-    rawParams,
-    m_programName,
-    pid);
-
-  writeMsgToUnderlyingLoggingSystem(os.str());
-}
-
-
-//-----------------------------------------------------------------------------
-// writeLogMsg
-//-----------------------------------------------------------------------------
-void Logger::writeLogMsg(
-  std::ostringstream &os,
-  const int priority,
-  const std::string &priorityText,
-  const std::string &msg,
-  const std::list<Param> &params,
-  const std::string &rawParams,
-  const std::string &programName,
-  const int pid) {
-
-  const int tid = syscall(__NR_gettid);
-
-  // Append the log level, the thread id and the message text
-  os << "LVL=\"" << priorityText << "\" PID=\"" << pid << "\" TID=\"" << tid << "\" MSG=\"" <<
-    msg << "\" ";
-
-  // Process parameters
-  for(auto itor = params.cbegin(); itor != params.cend(); itor++) {
-    const Param &param = *itor;
-
-    // Check the parameter name, if it's an empty string set the value to
-    // "Undefined".
-    const std::string name = param.getName() == "" ? "Undefined" :
-      cleanString(param.getName(), true);
-
-    // Process the parameter value
-    const std::string value = cleanString(param.getValue(), false);
-
-    // Write the name and value to the buffer
-    os << name << "=\"" << value << "\" ";
-  }
-
-  // Append raw parameters
-  os << rawParams;
+  writeMsgToUnderlyingLoggingSystem(header, body);
 }
 
 //-----------------------------------------------------------------------------
@@ -278,5 +223,76 @@ void Logger::setLogMask(const int logMask) {
   m_logMask = logMask;
 }
 
+//-----------------------------------------------------------------------------
+// createMsgHeader
+//-----------------------------------------------------------------------------
+std::string Logger::createMsgHeader(
+  const int priority,
+  const struct timeval &timeStamp,
+  const std::string &programName,
+  const int pid) {
+  std::ostringstream os;
+  char buf[80];
+  int bufLen = sizeof(buf);
+  int len = 0;
+
+  os << "<" << priority << ">";
+
+  struct tm localTime;
+  localtime_r(&(timeStamp.tv_sec), &localTime);
+  len += strftime(buf, bufLen, "%Y-%m-%dT%T", &localTime);
+  len += snprintf(buf + len, bufLen - len, ".%06ld",
+    (unsigned long)timeStamp.tv_usec);
+  len += strftime(buf + len, bufLen - len, "%z: ", &localTime);
+  // dirty trick to have the proper timezone format (':' between hh and mm)
+  buf[len-2] = buf[len-3];
+  buf[len-3] = buf[len-4];
+  buf[len-4] = ':';
+  buf[sizeof(buf) - 1] = '\0';
+  os << buf << programName << "[" << pid << "]: ";
+  return os.str();
+}
+
+//-----------------------------------------------------------------------------
+// createMsgBody
+//-----------------------------------------------------------------------------
+std::string Logger::createMsgBody(
+  const int priority,
+  const std::string &priorityText,
+  const std::string &msg,
+  const std::list<Param> &params,
+  const std::string &rawParams,
+  const std::string &programName,
+  const int pid) {
+  std::ostringstream os;
+
+  const int tid = syscall(__NR_gettid);
+
+  // Append the log level, the thread id and the message text
+  os << "LVL=\"" << priorityText << "\" PID=\"" << pid << "\" TID=\"" << tid << "\" MSG=\"" <<
+    msg << "\" ";
+
+  // Process parameters
+  for(auto itor = params.cbegin(); itor != params.cend(); itor++) {
+    const Param &param = *itor;
+
+    // Check the parameter name, if it's an empty string set the value to
+    // "Undefined".
+    const std::string name = param.getName() == "" ? "Undefined" :
+      cleanString(param.getName(), true);
+
+    // Process the parameter value
+    const std::string value = cleanString(param.getValue(), false);
+
+    // Write the name and value to the buffer
+    os << name << "=\"" << value << "\" ";
+  }
+
+  // Append raw parameters
+  os << rawParams;
+
+  return os.str();
+}
+
 } // namespace log
 } // namespace cta

common/log/Logger.hpp

@@ -109,8 +109,7 @@ public:
   virtual void prepareForFork() = 0;
 
   /**
-   * Returns the name of the program that is to  be prepended to every log
-   * message.
+   * Returns the name of the program.
    */
   const std::string &getProgramName() const;
 
@@ -169,9 +168,16 @@ protected:
    * This method is to be implemented by concrete sub-classes of the Logger
    * class.
    *
-   * @param msg The message to be logged.
+   * Please note it is the responsibility of a concrete sub-class to decide
+   * whether or not to use the specified log message header.  For example, the
+   * SysLogLogger sub-class does not use the header.  Instead it relies on
+   * rsyslog to provide a header.
+   *
+   * @param header The header of the message to be logged.  It is the
+   * esponsibility of the concrete sub-class 
+   * @param body The body of the message to be logged.
    */
-  virtual void writeMsgToUnderlyingLoggingSystem(const std::string &msg) = 0;
+  virtual void writeMsgToUnderlyingLoggingSystem(const std::string &header, const std::string &body) = 0;
 
   /**
    * The log mask.
@@ -193,27 +199,6 @@ protected:
    * their equivalent syslog priorities.
    */
   const std::map<std::string, int> m_configTextToPriority;
-
-  /**
-   * Writes a log message to the specified output stream.
-   *
-   * @param logMsg The output stream to which the log message is to be written.
-   * @param priority the priority of the message as defined by the syslog API.
-   * @param msg the message.
-   * @param params the parameters of the message.
-   * @param rawParams preprocessed parameters of the message.
-   * @param programName the program name of the log message.
-   * @param pid the pid of the log message.
-   */
-  static void writeLogMsg(
-    std::ostringstream &os,
-    const int priority,
-    const std::string &priorityText,
-    const std::string &msg,
-    const std::list<Param> &params,
-    const std::string &rawParams,
-    const std::string &programName,
-    const int pid);
   
   /**
    * Default size of a syslog message.
@@ -251,6 +236,47 @@ protected:
    */
   static std::map<std::string, int> generateConfigTextToPriorityMap();
 
+private:
+
+  /**
+   * Creates and returns the header of a log message.
+   *
+   * Concrete subclasses of the Logger class can decide whether or not to use
+   * message headers created by this method.  The SysLogger sub-class for example
+   * relies on rsyslog to provide message headers and therefore does not call
+   * this method.
+   *
+   * @param priority The priority of the message.
+   * @param timeStamp The time stamp of the message.
+   * @param programName the program name of the log message.
+   * @param pid The process ID of the process logging the message.
+   * @return The message header.
+   */
+  static std::string createMsgHeader(
+    const int priority,
+    const struct timeval &timeStamp,
+    const std::string &programName,
+    const int pid);
+
+  /**
+   * Creates and returns the body of a log message.
+   *
+   * @param priority the priority of the message as defined by the syslog API.
+   * @param msg the message.
+   * @param params the parameters of the message.
+   * @param rawParams preprocessed parameters of the message.
+   * @param programName the program name of the log message.
+   * @param pid the pid of the log message.
+   * @return The message body;
+   */
+  static std::string createMsgBody(
+    const int priority,
+    const std::string &priorityText,
+    const std::string &msg,
+    const std::list<Param> &params,
+    const std::string &rawParams,
+    const std::string &programName,
+    const int pid);
 
 }; // class Logger
 

common/log/StdoutLogger.cpp

@@ -42,9 +42,10 @@ void StdoutLogger::prepareForFork() {}
 //------------------------------------------------------------------------------
 // writeMsgToUnderlyingLoggingSystem
 //------------------------------------------------------------------------------
-void StdoutLogger::writeMsgToUnderlyingLoggingSystem(const std::string &msg) {
-  printf("%s\n", msg.c_str());
+void StdoutLogger::writeMsgToUnderlyingLoggingSystem(const std::string &header, const std::string &body) {
+  const std::string headerPlusBody = header + body;
+  printf("%s\n", headerPlusBody.c_str());
 }
 
 } // namespace log
-} // namespace cta
\ No newline at end of file
+} // namespace cta

common/log/StdoutLogger.hpp

@@ -53,14 +53,21 @@ public:
 protected:
 
   /**
-   * Writes the specified log message to the underlying logging system.
+   * Writes the specified msg to the underlying logging system.
    *
    * This method is to be implemented by concrete sub-classes of the Logger
    * class.
    *
-   * @param msg The message to be logged.
+   * Please note it is the responsibility of a concrete sub-class to decide
+   * whether or not to use the specified log message header.  For example, the
+   * SysLogLogger sub-class does not use the header.  Instead it relies on
+   * rsyslog to provide a header.
+   *
+   * @param header The header of the message to be logged.  It is the
+   * esponsibility of the concrete sub-class
+   * @param body The body of the message to be logged.
    */
-  void writeMsgToUnderlyingLoggingSystem(const std::string &msg) override;
+  void writeMsgToUnderlyingLoggingSystem(const std::string &header, const std::string &body) override;
 
 }; // class StringLogger
 

common/log/StringLogger.cpp

@@ -45,16 +45,18 @@ void StringLogger::prepareForFork() {
 //-----------------------------------------------------------------------------
 // writeMsgToUnderlyingLoggingSystem
 //-----------------------------------------------------------------------------
-void StringLogger::writeMsgToUnderlyingLoggingSystem(const std::string &msg) {
+void StringLogger::writeMsgToUnderlyingLoggingSystem(const std::string &header, const std::string &body) {
   // enter critical section
   threading::MutexLocker lock(m_mutex);
 
+  const std::string headerPlusBody = header + body;
+
   // Append the message to the log (truncated to the maximum length)
-  m_log << msg.substr(0, m_maxMsgLen) << std::endl;
+  m_log << headerPlusBody.substr(0, m_maxMsgLen) << std::endl;
 
   // Uncomment this to get the logs printed to stdout during unit tests.
   // printf ("%s\n", msg.substr(0, m_maxMsgLen).c_str());
 }
 
 } // namespace log
-} // namespace cta
\ No newline at end of file
+} // namespace cta

common/log/StringLogger.hpp

@@ -71,15 +71,21 @@ protected:
   std::stringstream m_log;
 
   /**
-   * Writes the specified log message to the underlying logging system.
+   * Writes the specified msg to the underlying logging system.
    *
    * This method is to be implemented by concrete sub-classes of the Logger
    * class.
    *
-   * @param msg The message to be logged.
+   * Please note it is the responsibility of a concrete sub-class to decide
+   * whether or not to use the specified log message header.  For example, the
+   * SysLogLogger sub-class does not use the header.  Instead it relies on
+   * rsyslog to provide a header.
+   *
+   * @param header The header of the message to be logged.  It is the
+   * esponsibility of the concrete sub-class
+   * @param body The body of the message to be logged.
    */
-  void writeMsgToUnderlyingLoggingSystem(const std::string &msg) override;
-
+  void writeMsgToUnderlyingLoggingSystem(const std::string &header, const std::string &body) override;
 }; // class StringLogger
 
 } // namespace log

common/log/SyslogLogger.cpp

@@ -65,9 +65,10 @@ void SyslogLogger::prepareForFork() {
 //-----------------------------------------------------------------------------
 // writeMsgToLoggingSystem
 //-----------------------------------------------------------------------------
-void SyslogLogger::writeMsgToUnderlyingLoggingSystem(const std::string &msg) {
+void SyslogLogger::writeMsgToUnderlyingLoggingSystem(const std::string &header, const std::string &body) {
+  // Explicitly ignore the message header as this will be provided by rsyslog
   // Truncate the log message if it exceeds the permitted maximum
-  std::string truncatedMsg = msg.substr(0, m_maxMsgLen);
+  std::string truncatedMsg = body.substr(0, m_maxMsgLen);
 
   syslog(LOG_LOCAL3|INFO, truncatedMsg.c_str());
 }

common/log/SyslogLogger.hpp

@@ -62,14 +62,21 @@ public:
 protected:
 
   /**
-   * Writes the specified log message to the underlying logging system.
+   * Writes the specified msg to the underlying logging system.
    *
    * This method is to be implemented by concrete sub-classes of the Logger
    * class.
    *
-   * @param msg The message to be logged.
+   * Please note it is the responsibility of a concrete sub-class to decide
+   * whether or not to use the specified log message header.  For example, the
+   * SysLogLogger sub-class does not use the header.  Instead it relies on
+   * rsyslog to provide a header.
+   *
+   * @param header The header of the message to be logged.  It is the
+   * esponsibility of the concrete sub-class
+   * @param body The body of the message to be logged.
    */
-  void writeMsgToUnderlyingLoggingSystem(const std::string &msg) override;
+  void writeMsgToUnderlyingLoggingSystem(const std::string &header, const std::string &body) override;
 
 }; // class SyslogLogger