Update default log formats to escape messages using JSON encoding rules

include/triton/common/error.h

@@ -36,7 +36,7 @@ namespace triton { namespace common {
 //
 class Error {
  public:
-  enum class Code {
+  enum class Code : uint8_t {
     SUCCESS,
     UNKNOWN,
     INTERNAL,

include/triton/common/logging.h

@@ -33,38 +33,46 @@
 #include <string>
 #include <vector>
 
-namespace triton { namespace common {
-
-// A log message.
-class LogMessage {
- public:
-  // Log levels.
-  enum Level { kERROR = 0, kWARNING = 1, kINFO = 2 };
+#include "table_printer.h"
+#ifdef _WIN32
+// suppress the min and max definitions in Windef.h.
+#define NOMINMAX
+#include <Windows.h>
+#else
+#include <sys/time.h>
+#include <sys/types.h>
+#include <time.h>
+#include <unistd.h>
+#endif
 
-  LogMessage(const char* file, int line, uint32_t level);
-  ~LogMessage();
 
-  std::stringstream& stream() { return stream_; }
+namespace triton { namespace common {
 
- private:
-  static const std::vector<char> level_name_;
-  std::stringstream stream_;
-};
 
 // Global logger for messages. Controls how log messages are reported.
 class Logger {
  public:
+  // Log Formats.
   enum class Format { kDEFAULT, kISO8601 };
 
+  // Log levels.
+  enum class Level : uint8_t { kERROR = 0, kWARNING = 1, kINFO = 2, kEND };
+
+  inline static const std::array<const char*, static_cast<uint8_t>(Level::kEND)>
+      LEVEL_NAMES{"E", "W", "I"};
+
   Logger();
 
   // Is a log level enabled.
-  bool IsEnabled(LogMessage::Level level) const { return enables_[level]; }
+  bool IsEnabled(Level level) const
+  {
+    return enables_[static_cast<uint8_t>(level)];
+  }
 
   // Set enable for a log Level.
-  void SetEnabled(LogMessage::Level level, bool enable)
+  void SetEnabled(Level level, bool enable)
   {
-    enables_[level] = enable;
+    enables_[static_cast<uint8_t>(level)] = enable;
   }
 
   // Get the current verbose logging level.
@@ -73,6 +81,16 @@ class Logger {
   // Set the current verbose logging level.
   void SetVerboseLevel(uint32_t vlevel) { vlevel_ = vlevel; }
 
+  // Whether to escape log messages
+  // using JSON string escaping rules.
+  // Default is true but can be disabled by setting
+  // the following environment variable to '0'.
+  // If the variable is unset or set to any value !='0'
+  // log messages will be escaped
+  //
+  // TRITON_SERVER_ESCAPE_LOG_MESSAGES=0
+  bool EscapeLogMessages() const { return escape_log_messages_; };
+
   // Get the logging format.
   Format LogFormat() { return format_; }
 
@@ -126,7 +144,10 @@ class Logger {
   void Flush();
 
  private:
-  std::vector<bool> enables_;
+  inline static const char* ESCAPE_ENVIRONMENT_VARIABLE =
+      "TRITON_SERVER_ESCAPE_LOG_MESSAGES";
+  bool escape_log_messages_;
+  std::array<bool, static_cast<uint8_t>(Level::kEND)> enables_;
   uint32_t vlevel_;
   Format format_;
   std::mutex mutex_;
@@ -136,15 +157,60 @@ class Logger {
 
 extern Logger gLogger_;
 
-#define LOG_ENABLE_INFO(E)             \
-  triton::common::gLogger_.SetEnabled( \
-      triton::common::LogMessage::Level::kINFO, (E))
+// A log message.
+class LogMessage {
+ public:
+  LogMessage(
+      const char* file, int line, Logger::Level level,
+      const char* heading = nullptr,
+      bool escape_log_messages = gLogger_.EscapeLogMessages())
+      : path_(file), line_(line), level_(level), pid_(GetProcessId()),
+        heading_(heading), escape_log_messages_(escape_log_messages)
+  {
+    SetTimestamp();
+    size_t path_start = path_.rfind('/');
+    if (path_start != std::string::npos) {
+      path_ = path_.substr(path_start + 1, std::string::npos);
+    }
+  }
+
+  ~LogMessage();
+
+  std::stringstream& stream() { return message_; }
+
+ private:
+  std::string path_;
+  const int line_;
+  const Logger::Level level_;
+  const uint32_t pid_;
+  void LogPreamble(std::stringstream& stream);
+  void LogTimestamp(std::stringstream& stream);
+
+#ifdef _WIN32
+  SYSTEMTIME timestamp_;
+  void SetTimestamp() { GetSystemTime(&timestamp_); }
+  static uint32_t GetProcessId()
+  {
+    return static_cast<uint32_t>(GetCurrentProcessId());
+  };
+#else
+  struct timeval timestamp_;
+  void SetTimestamp() { gettimeofday(&timestamp_, NULL); }
+  static uint32_t GetProcessId() { return static_cast<uint32_t>(getpid()); };
+#endif
+  std::stringstream message_;
+  const char* heading_;
+  bool escape_log_messages_;
+};
+
+#define LOG_ENABLE_INFO(E) \
+  triton::common::gLogger_.SetEnabled(triton::common::Logger::Level::kINFO, (E))
 #define LOG_ENABLE_WARNING(E)          \
   triton::common::gLogger_.SetEnabled( \
-      triton::common::LogMessage::Level::kWARNING, (E))
+      triton::common::Logger::Level::kWARNING, (E))
 #define LOG_ENABLE_ERROR(E)            \
   triton::common::gLogger_.SetEnabled( \
-      triton::common::LogMessage::Level::kERROR, (E))
+      triton::common::Logger::Level::kERROR, (E))
 #define LOG_SET_VERBOSE(L)                  \
   triton::common::gLogger_.SetVerboseLevel( \
       static_cast<uint32_t>(std::max(0, (L))))
@@ -159,12 +225,11 @@ extern Logger gLogger_;
 #ifdef TRITON_ENABLE_LOGGING
 
 #define LOG_INFO_IS_ON \
-  triton::common::gLogger_.IsEnabled(triton::common::LogMessage::Level::kINFO)
-#define LOG_WARNING_IS_ON             \
-  triton::common::gLogger_.IsEnabled( \
-      triton::common::LogMessage::Level::kWARNING)
+  triton::common::gLogger_.IsEnabled(triton::common::Logger::Level::kINFO)
+#define LOG_WARNING_IS_ON \
+  triton::common::gLogger_.IsEnabled(triton::common::Logger::Level::kWARNING)
 #define LOG_ERROR_IS_ON \
-  triton::common::gLogger_.IsEnabled(triton::common::LogMessage::Level::kERROR)
+  triton::common::gLogger_.IsEnabled(triton::common::Logger::Level::kERROR)
 #define LOG_VERBOSE_IS_ON(L) (triton::common::gLogger_.VerboseLevel() >= (L))
 
 #else
@@ -178,25 +243,25 @@ extern Logger gLogger_;
 #endif  // TRITON_ENABLE_LOGGING
 
 // Macros that use explicitly given filename and line number.
-#define LOG_INFO_FL(FN, LN)                                      \
-  if (LOG_INFO_IS_ON)                                            \
-  triton::common::LogMessage(                                    \
-      (char*)(FN), LN, triton::common::LogMessage::Level::kINFO) \
+#define LOG_INFO_FL(FN, LN)                                  \
+  if (LOG_INFO_IS_ON)                                        \
+  triton::common::LogMessage(                                \
+      (char*)(FN), LN, triton::common::Logger::Level::kINFO) \
       .stream()
-#define LOG_WARNING_FL(FN, LN)                                      \
-  if (LOG_WARNING_IS_ON)                                            \
-  triton::common::LogMessage(                                       \
-      (char*)(FN), LN, triton::common::LogMessage::Level::kWARNING) \
+#define LOG_WARNING_FL(FN, LN)                                  \
+  if (LOG_WARNING_IS_ON)                                        \
+  triton::common::LogMessage(                                   \
+      (char*)(FN), LN, triton::common::Logger::Level::kWARNING) \
       .stream()
-#define LOG_ERROR_FL(FN, LN)                                      \
-  if (LOG_ERROR_IS_ON)                                            \
-  triton::common::LogMessage(                                     \
-      (char*)(FN), LN, triton::common::LogMessage::Level::kERROR) \
+#define LOG_ERROR_FL(FN, LN)                                  \
+  if (LOG_ERROR_IS_ON)                                        \
+  triton::common::LogMessage(                                 \
+      (char*)(FN), LN, triton::common::Logger::Level::kERROR) \
       .stream()
-#define LOG_VERBOSE_FL(L, FN, LN)                                \
-  if (LOG_VERBOSE_IS_ON(L))                                      \
-  triton::common::LogMessage(                                    \
-      (char*)(FN), LN, triton::common::LogMessage::Level::kINFO) \
+#define LOG_VERBOSE_FL(L, FN, LN)                            \
+  if (LOG_VERBOSE_IS_ON(L))                                  \
+  triton::common::LogMessage(                                \
+      (char*)(FN), LN, triton::common::Logger::Level::kINFO) \
       .stream()
 
 // Macros that use current filename and line number.
@@ -205,7 +270,50 @@ extern Logger gLogger_;
 #define LOG_ERROR LOG_ERROR_FL(__FILE__, __LINE__)
 #define LOG_VERBOSE(L) LOG_VERBOSE_FL(L, __FILE__, __LINE__)
 
+// Macros for use with triton::common::table_printer objects
+//
+// Data is assumed to be server / backend generated
+// and not for use with client input.
+//
+// Tables are printed without escaping
+#define LOG_TABLE_VERBOSE(L, TABLE)                                          \
+                                                                             \
+  do {                                                                       \
+    if (LOG_VERBOSE_IS_ON(L))                                                \
+      triton::common::LogMessage(                                            \
+          __FILE__, __LINE__, triton::common::Logger::Level::kINFO, nullptr, \
+          false)                                                             \
+              .stream()                                                      \
+          << TABLE.PrintTable();                                             \
+  } while (false)
+
+#define LOG_TABLE_INFO(TABLE)                                                \
+  do {                                                                       \
+    if (LOG_INFO_IS_ON)                                                      \
+      triton::common::LogMessage(                                            \
+          __FILE__, __LINE__, triton::common::Logger::Level::kINFO, nullptr, \
+          false)                                                             \
+              .stream()                                                      \
+          << TABLE.PrintTable();                                             \
+  } while (false)
+
+
+// Macros for use with protobuf messages
+//
+// Data is serialized via DebugString()
+//
+// Data is printed without further escaping
+#define LOG_PROTOBUF_VERBOSE(L, HEADING, PB_MESSAGE)                         \
+  do {                                                                       \
+    if (LOG_VERBOSE_IS_ON(L))                                                \
+      triton::common::LogMessage(                                            \
+          __FILE__, __LINE__, triton::common::Logger::Level::kINFO, HEADING, \
+          false)                                                             \
+              .stream()                                                      \
+          << PB_MESSAGE.DebugString();                                       \
+  } while (false)
 
+// Macros for logging errors
 #define LOG_STATUS_ERROR(X, MSG)                         \
   do {                                                   \
     const Status& status__ = (X);                        \

include/triton/common/triton_json.h

@@ -109,6 +109,25 @@ class TritonJson {
     std::string buffer_;
   };
 
+  //
+  // Utility to serialize input string
+  // as a JSON string value
+
+  static std::string SerializeString(const std::string& input)
+  {
+    WriteBuffer writebuffer;
+    const unsigned int writeFlags = rapidjson::kWriteNanAndInfFlag;
+    // Provide default template arguments to pass writeFlags
+    rapidjson::Writer<
+        WriteBuffer, rapidjson::UTF8<>, rapidjson::UTF8<>,
+        rapidjson::CrtAllocator, writeFlags>
+        writer(writebuffer);
+    if (RAPIDJSON_UNLIKELY(!writer.String(input.c_str()))) {
+      return "Error Serializing String";
+    }
+    return writebuffer.Contents();
+  }
+
   //
   // Value representing the entire document or an element within a
   // document.

src/CMakeLists.txt

@@ -66,6 +66,7 @@ target_include_directories(
     $<INSTALL_INTERFACE:include>
     $<BUILD_INTERFACE:${CMAKE_CURRENT_SOURCE_DIR}/../include>
   PRIVATE
+    ${RAPIDJSON_INCLUDE_DIRS}
     ${CMAKE_CURRENT_SOURCE_DIR}
 )