// Copyright Epic Games, Inc. All Rights Reserved. #include "zenutil/logging.h" #undef ZEN_USE_SENTRY #define ZEN_USE_SENTRY 0 #if !defined(ZEN_USE_SENTRY) # if ZEN_PLATFORM_MAC && ZEN_ARCH_ARM64 // vcpkg's sentry-native port does not support Arm on Mac. # define ZEN_USE_SENTRY 0 # else # define ZEN_USE_SENTRY 1 # endif #endif ZEN_THIRD_PARTY_INCLUDES_START #include #include #include #include #include #include #include #include #include #if ZEN_USE_SENTRY # include #endif ZEN_THIRD_PARTY_INCLUDES_END #include #include #include #include // Custom logging -- test code, this should be tweaked namespace zen::logging { using namespace spdlog; using namespace spdlog::details; using namespace std::literals; class full_formatter final : public spdlog::formatter { public: full_formatter(std::string_view LogId, std::chrono::time_point Epoch) : m_Epoch(Epoch), m_LogId(LogId) {} virtual std::unique_ptr clone() const override { return std::make_unique(m_LogId, m_Epoch); } static constexpr bool UseDate = false; virtual void format(const details::log_msg& msg, memory_buf_t& dest) override { using std::chrono::duration_cast; using std::chrono::milliseconds; using std::chrono::seconds; if constexpr (UseDate) { auto secs = std::chrono::duration_cast(msg.time.time_since_epoch()); if (secs != m_LastLogSecs) { m_CachedTm = os::localtime(log_clock::to_time_t(msg.time)); m_LastLogSecs = secs; } } const auto& tm_time = m_CachedTm; // cache the date/time part for the next second. auto duration = msg.time - m_Epoch; auto secs = duration_cast(duration); if (m_CacheTimestamp != secs || m_CachedDatetime.size() == 0) { m_CachedDatetime.clear(); m_CachedDatetime.push_back('['); if constexpr (UseDate) { fmt_helper::append_int(tm_time.tm_year + 1900, m_CachedDatetime); m_CachedDatetime.push_back('-'); fmt_helper::pad2(tm_time.tm_mon + 1, m_CachedDatetime); m_CachedDatetime.push_back('-'); fmt_helper::pad2(tm_time.tm_mday, m_CachedDatetime); m_CachedDatetime.push_back(' '); fmt_helper::pad2(tm_time.tm_hour, m_CachedDatetime); m_CachedDatetime.push_back(':'); fmt_helper::pad2(tm_time.tm_min, m_CachedDatetime); m_CachedDatetime.push_back(':'); fmt_helper::pad2(tm_time.tm_sec, m_CachedDatetime); } else { int Count = int(secs.count()); const int LogSecs = Count % 60; Count /= 60; const int LogMins = Count % 60; Count /= 60; const int LogHours = Count; fmt_helper::pad2(LogHours, m_CachedDatetime); m_CachedDatetime.push_back(':'); fmt_helper::pad2(LogMins, m_CachedDatetime); m_CachedDatetime.push_back(':'); fmt_helper::pad2(LogSecs, m_CachedDatetime); } m_CachedDatetime.push_back('.'); m_CacheTimestamp = secs; } dest.append(m_CachedDatetime.begin(), m_CachedDatetime.end()); auto millis = fmt_helper::time_fraction(msg.time); fmt_helper::pad3(static_cast(millis.count()), dest); dest.push_back(']'); dest.push_back(' '); if (!m_LogId.empty()) { dest.push_back('['); fmt_helper::append_string_view(m_LogId, dest); dest.push_back(']'); dest.push_back(' '); } // append logger name if exists if (msg.logger_name.size() > 0) { dest.push_back('['); fmt_helper::append_string_view(msg.logger_name, dest); dest.push_back(']'); dest.push_back(' '); } dest.push_back('['); // wrap the level name with color msg.color_range_start = dest.size(); fmt_helper::append_string_view(level::to_string_view(msg.level), dest); msg.color_range_end = dest.size(); dest.push_back(']'); dest.push_back(' '); // add source location if present if (!msg.source.empty()) { dest.push_back('['); const char* filename = details::short_filename_formatter::basename(msg.source.filename); fmt_helper::append_string_view(filename, dest); dest.push_back(':'); fmt_helper::append_int(msg.source.line, dest); dest.push_back(']'); dest.push_back(' '); } fmt_helper::append_string_view(msg.payload, dest); fmt_helper::append_string_view("\n"sv, dest); } private: std::chrono::time_point m_Epoch; std::tm m_CachedTm; std::chrono::seconds m_LastLogSecs; std::chrono::seconds m_CacheTimestamp{0}; memory_buf_t m_CachedDatetime; std::string m_LogId; }; class json_formatter final : public spdlog::formatter { public: json_formatter(std::string_view LogId) : m_LogId(LogId) {} virtual std::unique_ptr clone() const override { return std::make_unique(m_LogId); } virtual void format(const details::log_msg& msg, memory_buf_t& dest) override { using std::chrono::duration_cast; using std::chrono::milliseconds; using std::chrono::seconds; auto secs = std::chrono::duration_cast(msg.time.time_since_epoch()); if (secs != m_LastLogSecs) { m_CachedTm = os::localtime(log_clock::to_time_t(msg.time)); m_LastLogSecs = secs; } const auto& tm_time = m_CachedTm; // cache the date/time part for the next second. if (m_CacheTimestamp != secs || m_CachedDatetime.size() == 0) { m_CachedDatetime.clear(); fmt_helper::append_int(tm_time.tm_year + 1900, m_CachedDatetime); m_CachedDatetime.push_back('-'); fmt_helper::pad2(tm_time.tm_mon + 1, m_CachedDatetime); m_CachedDatetime.push_back('-'); fmt_helper::pad2(tm_time.tm_mday, m_CachedDatetime); m_CachedDatetime.push_back(' '); fmt_helper::pad2(tm_time.tm_hour, m_CachedDatetime); m_CachedDatetime.push_back(':'); fmt_helper::pad2(tm_time.tm_min, m_CachedDatetime); m_CachedDatetime.push_back(':'); fmt_helper::pad2(tm_time.tm_sec, m_CachedDatetime); m_CachedDatetime.push_back('.'); m_CacheTimestamp = secs; } dest.append("{"sv); dest.append("\"time\": \""sv); dest.append(m_CachedDatetime.begin(), m_CachedDatetime.end()); auto millis = fmt_helper::time_fraction(msg.time); fmt_helper::pad3(static_cast(millis.count()), dest); dest.append("\", "sv); dest.append("\"status\": \""sv); dest.append(level::to_string_view(msg.level)); dest.append("\", "sv); dest.append("\"source\": \""sv); dest.append("zenserver"sv); dest.append("\", "sv); dest.append("\"service\": \""sv); dest.append("zencache"sv); dest.append("\", "sv); if (!m_LogId.empty()) { dest.append("\"id\": \""sv); dest.append(m_LogId); dest.append("\", "sv); } if (msg.logger_name.size() > 0) { dest.append("\"logger.name\": \""sv); dest.append(msg.logger_name); dest.append("\", "sv); } if (msg.thread_id != 0) { dest.append("\"logger.thread_name\": \""sv); fmt_helper::pad_uint(msg.thread_id, 0, dest); dest.append("\", "sv); } if (!msg.source.empty()) { dest.append("\"file\": \""sv); WriteEscapedString(dest, details::short_filename_formatter::basename(msg.source.filename)); dest.append("\","sv); dest.append("\"line\": \""sv); dest.append(fmt::format("{}", msg.source.line)); dest.append("\","sv); dest.append("\"logger.method_name\": \""sv); WriteEscapedString(dest, msg.source.funcname); dest.append("\", "sv); } dest.append("\"message\": \""sv); WriteEscapedString(dest, msg.payload); dest.append("\""sv); dest.append("}\n"sv); } private: static inline const std::unordered_map SpecialCharacterMap{{'\b', "\\b"sv}, {'\f', "\\f"sv}, {'\n', "\\n"sv}, {'\r', "\\r"sv}, {'\t', "\\t"sv}, {'"', "\\\""sv}, {'\\', "\\\\"sv}}; static void WriteEscapedString(memory_buf_t& dest, const spdlog::string_view_t& payload) { const char* RangeStart = payload.begin(); for (const char* It = RangeStart; It != payload.end(); ++It) { if (auto SpecialIt = SpecialCharacterMap.find(*It); SpecialIt != SpecialCharacterMap.end()) { if (RangeStart != It) { dest.append(RangeStart, It); } dest.append(SpecialIt->second); RangeStart = It + 1; } } if (RangeStart != payload.end()) { dest.append(RangeStart, payload.end()); } }; std::tm m_CachedTm{0, 0, 0, 0, 0, 0, 0, 0, 0}; std::chrono::seconds m_LastLogSecs{0}; std::chrono::seconds m_CacheTimestamp{0}; memory_buf_t m_CachedDatetime; std::string m_LogId; }; } // namespace zen::logging bool EnableVTMode() { #if ZEN_PLATFORM_WINDOWS // Set output mode to handle virtual terminal sequences HANDLE hOut = GetStdHandle(STD_OUTPUT_HANDLE); if (hOut == INVALID_HANDLE_VALUE) { return false; } DWORD dwMode = 0; if (!GetConsoleMode(hOut, &dwMode)) { return false; } dwMode |= ENABLE_VIRTUAL_TERMINAL_PROCESSING; if (!SetConsoleMode(hOut, dwMode)) { return false; } #endif return true; } #if ZEN_USE_SENTRY class sentry_sink final : public spdlog::sinks::base_sink { public: sentry_sink() {} protected: static constexpr sentry_level_t MapToSentryLevel[spdlog::level::level_enum::n_levels] = {SENTRY_LEVEL_DEBUG, SENTRY_LEVEL_DEBUG, SENTRY_LEVEL_INFO, SENTRY_LEVEL_WARNING, SENTRY_LEVEL_ERROR, SENTRY_LEVEL_FATAL, SENTRY_LEVEL_DEBUG}; void sink_it_(const spdlog::details::log_msg& msg) override { if (msg.level >= SPDLOG_LEVEL_ERROR && msg.level <= SPDLOG_LEVEL_CRITICAL) { sentry_value_t event = sentry_value_new_message_event( /* level */ MapToSentryLevel[msg.level], /* logger */ nullptr, /* message */ std::string(msg.payload.data(), msg.payload.size()).c_str()); sentry_event_value_add_stacktrace(event, NULL, 0); sentry_capture_event(event); } } void flush_() override {} }; #endif namespace zen { void InitializeLogging(const LoggingOptions& LogOptions) { zen::logging::InitializeLogging(); EnableVTMode(); bool IsAsync = true; spdlog::level::level_enum LogLevel = spdlog::level::info; if (LogOptions.IsDebug) { LogLevel = spdlog::level::debug; IsAsync = false; } if (LogOptions.IsTest) { LogLevel = spdlog::level::trace; IsAsync = false; } if (IsAsync) { const int QueueSize = 8192; const int ThreadCount = 1; spdlog::init_thread_pool(QueueSize, ThreadCount); auto AsyncLogger = spdlog::create_async("main"); zen::logging::SetDefault(AsyncLogger); } // Sinks auto ConsoleSink = std::make_shared(); spdlog::sink_ptr FileSink; spdlog::sink_ptr SentrySink; // spdlog can't create directories that starts with `\\?\` so we make sure the folder exists before creating the logger instance if (!LogOptions.AbsLogFile.empty()) { if (LogOptions.AbsLogFile.has_parent_path()) { zen::CreateDirectories(LogOptions.AbsLogFile.parent_path()); } #if 0 FileSink = std::make_shared( zen::PathToUtf8(GlobalOptions.AbsLogFile), 0, 0, /* truncate */ false, uint16_t(/* max files */ 14)); #else FileSink = std::make_shared(zen::PathToUtf8(LogOptions.AbsLogFile), /* max size */ 128 * 1024 * 1024, /* max files */ 16, /* rotate on open */ true); #endif } #if ZEN_USE_SENTRY SentrySink = std::make_shared(); #endif std::set_terminate([]() { ZEN_CRITICAL("Program exited abnormally via std::terminate()"); }); // Default auto& DefaultLogger = zen::logging::Default(); auto& Sinks = DefaultLogger.sinks(); Sinks.clear(); Sinks.push_back(ConsoleSink); if (FileSink) { Sinks.push_back(FileSink); } if (SentrySink) { Sinks.push_back(SentrySink); } #if ZEN_PLATFORM_WINDOWS if (zen::IsDebuggerPresent() && LogOptions.IsDebug) { auto DebugSink = std::make_shared(); DebugSink->set_level(spdlog::level::debug); Sinks.push_back(DebugSink); } #endif // Configure all registered loggers according to settings spdlog::set_level(LogLevel); spdlog::flush_on(spdlog::level::err); spdlog::flush_every(std::chrono::seconds{2}); spdlog::set_formatter(std::make_unique(LogOptions.LogId, std::chrono::system_clock::now())); if (FileSink) { if (LogOptions.AbsLogFile.extension() == ".json") { FileSink->set_formatter(std::make_unique(LogOptions.LogId)); } else { FileSink->set_pattern("[%C-%m-%d.%e %T] [%n] [%l] %v"); } } DefaultLogger.info("log starting at {:%FT%T%z}", std::chrono::system_clock::now()); } void ShutdownLogging() { auto& DefaultLogger = zen::logging::Default(); DefaultLogger.info("log ending at {:%FT%T%z}", std::chrono::system_clock::now()); zen::logging::ShutdownLogging(); } } // namespace zen