From d6e35062eab22e0391520b1abee54f5c0588867d Mon Sep 17 00:00:00 2001 From: Neelay Shah Date: Tue, 21 May 2024 08:52:20 -0700 Subject: [PATCH 1/2] adding explicit include of array --- include/triton/common/logging.h | 1 + 1 file changed, 1 insertion(+) diff --git a/include/triton/common/logging.h b/include/triton/common/logging.h index 0be8df4..fab6b54 100644 --- a/include/triton/common/logging.h +++ b/include/triton/common/logging.h @@ -25,6 +25,7 @@ // OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. #pragma once +#include #include #include #include From b35a3750aed3cfcd84bc6438f37dc13dc5d09ef9 Mon Sep 17 00:00:00 2001 From: nnshah1 Date: Tue, 21 May 2024 11:14:17 -0700 Subject: [PATCH 2/2] Update default log formats to escape messages using JSON encoding rules --- include/triton/common/error.h | 2 +- include/triton/common/logging.h | 196 +++++++++++++++++++++------- include/triton/common/triton_json.h | 19 +++ src/CMakeLists.txt | 1 + src/logging.cc | 153 ++++++++++++---------- 5 files changed, 255 insertions(+), 116 deletions(-) diff --git a/include/triton/common/error.h b/include/triton/common/error.h index 5c22c19..45841a7 100644 --- a/include/triton/common/error.h +++ b/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, diff --git a/include/triton/common/logging.h b/include/triton/common/logging.h index fab6b54..e415cd0 100644 --- a/include/triton/common/logging.h +++ b/include/triton/common/logging.h @@ -34,38 +34,46 @@ #include #include -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 +#else +#include +#include +#include +#include +#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 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(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(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(level)] = enable; } // Get the current verbose logging level. @@ -74,6 +82,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_; } @@ -127,7 +145,10 @@ class Logger { void Flush(); private: - std::vector enables_; + inline static const char* ESCAPE_ENVIRONMENT_VARIABLE = + "TRITON_SERVER_ESCAPE_LOG_MESSAGES"; + bool escape_log_messages_; + std::array(Level::kEND)> enables_; uint32_t vlevel_; Format format_; std::mutex mutex_; @@ -137,15 +158,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(×tamp_); } + static uint32_t GetProcessId() + { + return static_cast(GetCurrentProcessId()); + }; +#else + struct timeval timestamp_; + void SetTimestamp() { gettimeofday(×tamp_, NULL); } + static uint32_t GetProcessId() { return static_cast(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(std::max(0, (L)))) @@ -160,12 +226,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 @@ -179,25 +244,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. @@ -206,7 +271,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); \ diff --git a/include/triton/common/triton_json.h b/include/triton/common/triton_json.h index 7a1b052..d57ff6e 100644 --- a/include/triton/common/triton_json.h +++ b/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. diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt index 85ebda6..4c98094 100644 --- a/src/CMakeLists.txt +++ b/src/CMakeLists.txt @@ -66,6 +66,7 @@ target_include_directories( $ $ PRIVATE + ${RAPIDJSON_INCLUDE_DIRS} ${CMAKE_CURRENT_SOURCE_DIR} ) diff --git a/src/logging.cc b/src/logging.cc index 67b01ba..978c1e5 100644 --- a/src/logging.cc +++ b/src/logging.cc @@ -24,22 +24,18 @@ // (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE // OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. -#include "triton/common/logging.h" - -#ifdef _WIN32 -// suppress the min and max definitions in Windef.h. -#define NOMINMAX -#include -#else -#include -#include -#include -#include -#endif #include #include #include +// Defined but not used +#define TRITONJSON_STATUSTYPE uint8_t +#define TRITONJSON_STATUSRETURN(M) +#define TRITONJSON_STATUSSUCCESS 0 + +#include "triton/common/logging.h" +#include "triton/common/triton_json.h" + namespace triton { namespace common { Logger gLogger_; @@ -47,6 +43,8 @@ Logger gLogger_; Logger::Logger() : enables_{true, true, true}, vlevel_(0), format_(Format::kDEFAULT) { + const char* value = std::getenv(Logger::ESCAPE_ENVIRONMENT_VARIABLE); + escape_log_messages_ = (value && std::strcmp(value, "0") == 0) ? false : true; } void @@ -66,82 +64,95 @@ Logger::Flush() std::cerr << std::flush; } +#ifdef _WIN32 -const std::vector LogMessage::level_name_{'E', 'W', 'I'}; - -LogMessage::LogMessage(const char* file, int line, uint32_t level) +void +LogMessage::LogTimestamp(std::stringstream& stream) { - std::string path(file); - size_t pos = path.rfind('/'); - if (pos != std::string::npos) { - path = path.substr(pos + 1, std::string::npos); + switch (gLogger_.LogFormat()) { + case Logger::Format::kDEFAULT: { + stream << std::setfill('0') << std::setw(2) << timestamp_.wMonth + << std::setw(2) << timestamp_.wDay << ' ' << std::setw(2) + << timestamp_.wHour << ':' << std::setw(2) << timestamp_.wMinute + << ':' << std::setw(2) << timestamp_.wSecond << '.' << std::setw(6) + << timestamp_.wMilliseconds * 1000; + break; + } + case Logger::Format::kISO8601: { + stream << timestamp_.wYear << '-' << std::setfill('0') << std::setw(2) + << timestamp_.wMonth << '-' << std::setw(2) << timestamp_.wDay + << 'T' << std::setw(2) << timestamp_.wHour << ':' << std::setw(2) + << timestamp_.wMinute << ':' << std::setw(2) << timestamp_.wSecond + << "Z"; + break; + } } +} +#else +void +LogMessage::LogTimestamp(std::stringstream& stream) +{ + struct tm tm_time; + gmtime_r(((time_t*)&(timestamp_.tv_sec)), &tm_time); - // 'L' below is placeholder for showing log level switch (gLogger_.LogFormat()) { case Logger::Format::kDEFAULT: { - // LMMDD hh:mm:ss.ssssss -#ifdef _WIN32 - SYSTEMTIME system_time; - GetSystemTime(&system_time); - stream_ << level_name_[std::min(level, (uint32_t)Level::kINFO)] - << std::setfill('0') << std::setw(2) << system_time.wMonth - << std::setw(2) << system_time.wDay << ' ' << std::setw(2) - << system_time.wHour << ':' << std::setw(2) << system_time.wMinute - << ':' << std::setw(2) << system_time.wSecond << '.' - << std::setw(6) << system_time.wMilliseconds * 1000 << ' ' - << static_cast(GetCurrentProcessId()) << ' ' << path - << ':' << line << "] "; -#else - struct timeval tv; - gettimeofday(&tv, NULL); - struct tm tm_time; - gmtime_r(((time_t*)&(tv.tv_sec)), &tm_time); - stream_ << level_name_[std::min(level, (uint32_t)Level::kINFO)] - << std::setfill('0') << std::setw(2) << (tm_time.tm_mon + 1) - << std::setw(2) << tm_time.tm_mday << ' ' << std::setw(2) - << tm_time.tm_hour << ':' << std::setw(2) << tm_time.tm_min << ':' - << std::setw(2) << tm_time.tm_sec << '.' << std::setw(6) - << tv.tv_usec << ' ' << static_cast(getpid()) << ' ' - << path << ':' << line << "] "; -#endif + stream << std::setfill('0') << std::setw(2) << (tm_time.tm_mon + 1) + << std::setw(2) << tm_time.tm_mday << ' ' << std::setw(2) + << tm_time.tm_hour << ':' << std::setw(2) << tm_time.tm_min << ':' + << std::setw(2) << tm_time.tm_sec << '.' << std::setw(6) + << timestamp_.tv_usec; break; } case Logger::Format::kISO8601: { - // YYYY-MM-DDThh:mm:ssZ L -#ifdef _WIN32 - SYSTEMTIME system_time; - GetSystemTime(&system_time); - stream_ << system_time.wYear << '-' << std::setfill('0') << std::setw(2) - << system_time.wMonth << '-' << std::setw(2) << system_time.wDay - << 'T' << std::setw(2) << system_time.wHour << ':' << std::setw(2) - << system_time.wMinute << ':' << std::setw(2) - << system_time.wSecond << "Z " - << level_name_[std::min(level, (uint32_t)Level::kINFO)] << ' ' - << static_cast(GetCurrentProcessId()) << ' ' << path - << ':' << line << "] "; -#else - struct timeval tv; - gettimeofday(&tv, NULL); - struct tm tm_time; - gmtime_r(((time_t*)&(tv.tv_sec)), &tm_time); - stream_ << (tm_time.tm_year + 1900) << '-' << std::setfill('0') - << std::setw(2) << (tm_time.tm_mon + 1) << '-' << std::setw(2) - << tm_time.tm_mday << 'T' << std::setw(2) << tm_time.tm_hour - << ':' << std::setw(2) << tm_time.tm_min << ':' << std::setw(2) - << tm_time.tm_sec << "Z " - << level_name_[std::min(level, (uint32_t)Level::kINFO)] << ' ' - << static_cast(getpid()) << ' ' << path << ':' << line - << "] "; + stream << (tm_time.tm_year + 1900) << '-' << std::setfill('0') + << std::setw(2) << (tm_time.tm_mon + 1) << '-' << std::setw(2) + << tm_time.tm_mday << 'T' << std::setw(2) << tm_time.tm_hour << ':' + << std::setw(2) << tm_time.tm_min << ':' << std::setw(2) + << tm_time.tm_sec << "Z"; + break; + } + } +} + #endif + +void +LogMessage::LogPreamble(std::stringstream& stream) +{ + switch (gLogger_.LogFormat()) { + case Logger::Format::kDEFAULT: { + stream << Logger::LEVEL_NAMES[static_cast(level_)]; + LogTimestamp(stream); + stream << ' ' << pid_ << ' ' << path_ << ':' << line_ << "] "; + + break; + } + case Logger::Format::kISO8601: { + LogTimestamp(stream); + stream << " " << Logger::LEVEL_NAMES[static_cast(level_)] << ' ' + << pid_ << ' ' << path_ << ':' << line_ << "] "; break; } } } + LogMessage::~LogMessage() { - gLogger_.Log(stream_.str()); + std::stringstream log_record; + LogPreamble(log_record); + std::string escaped_message = + escape_log_messages_ ? TritonJson::SerializeString(message_.str()) + : message_.str(); + if (heading_ != nullptr) { + std::string escaped_heading = gLogger_.EscapeLogMessages() + ? TritonJson::SerializeString(heading_) + : heading_; + log_record << escaped_heading << '\n'; + } + log_record << escaped_message; + gLogger_.Log(log_record.str()); } }} // namespace triton::common