diff options
| author | Stefan Boberg <[email protected]> | 2023-10-12 15:27:55 +0200 |
|---|---|---|
| committer | Stefan Boberg <[email protected]> | 2023-10-12 15:27:55 +0200 |
| commit | 83f4c7f9f564febbcc5895337e2cbc340d7da441 (patch) | |
| tree | ff3514b444bc6943e2668f8f145bf1c9b00556fc /src | |
| parent | Change default port to 8558 (diff) | |
| parent | Update README.md (diff) | |
| download | zen-83f4c7f9f564febbcc5895337e2cbc340d7da441.tar.xz zen-83f4c7f9f564febbcc5895337e2cbc340d7da441.zip | |
Merge remote-tracking branch 'origin/main' into zs/default-port-change
Diffstat (limited to 'src')
| -rw-r--r-- | src/transports/README.md | 5 | ||||
| -rw-r--r-- | src/transports/transport-sdk/include/transportplugin.h (renamed from src/plugins/include/transportplugin.h) | 0 | ||||
| -rw-r--r-- | src/transports/transport-sdk/xmake.lua (renamed from src/plugins/xmake.lua) | 4 | ||||
| -rw-r--r-- | src/transports/winsock/winsock.cpp (renamed from src/plugins/winsock/winsock.cpp) | 0 | ||||
| -rw-r--r-- | src/transports/winsock/xmake.lua (renamed from src/plugins/winsock/xmake.lua) | 2 | ||||
| -rw-r--r-- | src/transports/xmake.lua | 10 | ||||
| -rw-r--r-- | src/zenhttp/httpserver.cpp | 3 | ||||
| -rw-r--r-- | src/zenhttp/httpsys.cpp | 82 | ||||
| -rw-r--r-- | src/zenhttp/httpsys.h | 1 | ||||
| -rw-r--r-- | src/zenhttp/include/zenhttp/httpserver.h | 3 | ||||
| -rw-r--r-- | src/zenhttp/iothreadpool.cpp | 11 | ||||
| -rw-r--r-- | src/zenhttp/iothreadpool.h | 8 | ||||
| -rw-r--r-- | src/zenhttp/xmake.lua | 2 | ||||
| -rw-r--r-- | src/zenserver/config.cpp | 2 | ||||
| -rw-r--r-- | src/zenstore/gc.cpp | 50 | ||||
| -rw-r--r-- | src/zenutil/include/zenutil/logging.h | 33 | ||||
| -rw-r--r-- | src/zenutil/logging.cpp | 516 |
17 files changed, 682 insertions, 50 deletions
diff --git a/src/transports/README.md b/src/transports/README.md new file mode 100644 index 000000000..a4079f178 --- /dev/null +++ b/src/transports/README.md @@ -0,0 +1,5 @@ +This code corresponds to the code in [UE5/Engine/Source/Developer/ZenPluggableTransport](https://github.com/EpicGames/UnrealEngine/tree/release/Engine/Source/Developer),
+and provides the API definitions for creating transport plug-ins for use with the
+Zen server. Pluggable transports allow us to support a variety of transport mechanisms,
+including some which are not possible to share with a general audience. These are
+developed and maintained in the UE tree or elsewhere for logistical and legal reasons.
diff --git a/src/plugins/include/transportplugin.h b/src/transports/transport-sdk/include/transportplugin.h index aee5b2e7a..aee5b2e7a 100644 --- a/src/plugins/include/transportplugin.h +++ b/src/transports/transport-sdk/include/transportplugin.h diff --git a/src/plugins/xmake.lua b/src/transports/transport-sdk/xmake.lua index 9e4d49685..60387c26f 100644 --- a/src/plugins/xmake.lua +++ b/src/transports/transport-sdk/xmake.lua @@ -1,7 +1,7 @@ -- Copyright Epic Games, Inc. All Rights Reserved. -target('plugins') +target('transport-sdk') set_kind("headeronly") - set_group("plugins") + set_group("transports") add_headerfiles("**.h") add_includedirs("include", {public=true}) diff --git a/src/plugins/winsock/winsock.cpp b/src/transports/winsock/winsock.cpp index 25e46b2fb..25e46b2fb 100644 --- a/src/plugins/winsock/winsock.cpp +++ b/src/transports/winsock/winsock.cpp diff --git a/src/plugins/winsock/xmake.lua b/src/transports/winsock/xmake.lua index 408a248b1..9f9a32daf 100644 --- a/src/plugins/winsock/xmake.lua +++ b/src/transports/winsock/xmake.lua @@ -7,7 +7,7 @@ target("winsock") add_links("Ws2_32") add_includedirs(".", "../../zencore/include") set_symbols("debug") - add_deps("plugins") + add_deps("transport-sdk") if is_mode("release") then set_optimize("fastest") diff --git a/src/transports/xmake.lua b/src/transports/xmake.lua new file mode 100644 index 000000000..44800a8af --- /dev/null +++ b/src/transports/xmake.lua @@ -0,0 +1,10 @@ +-- Copyright Epic Games, Inc. All Rights Reserved. + +set_warnings("allextra", "error") +set_languages("cxx20") + +includes('transport-sdk') + +if is_plat("windows") then + includes("winsock") +end diff --git a/src/zenhttp/httpserver.cpp b/src/zenhttp/httpserver.cpp index 6dd40bd0e..7ea7cf91d 100644 --- a/src/zenhttp/httpserver.cpp +++ b/src/zenhttp/httpserver.cpp @@ -792,7 +792,8 @@ CreateHttpServer(const HttpServerConfig& Config) return Ref<HttpServer>(CreateHttpSysServer({.ThreadCount = Config.ThreadCount, .AsyncWorkThreadCount = Config.HttpSys.AsyncWorkThreadCount, .IsAsyncResponseEnabled = Config.HttpSys.IsAsyncResponseEnabled, - .IsRequestLoggingEnabled = Config.HttpSys.IsRequestLoggingEnabled})); + .IsRequestLoggingEnabled = Config.HttpSys.IsRequestLoggingEnabled, + .IsDedicatedServer = Config.IsDedicatedServer})); #endif case HttpServerClass::kHttpNull: diff --git a/src/zenhttp/httpsys.cpp b/src/zenhttp/httpsys.cpp index 993b065c0..c1b4717cb 100644 --- a/src/zenhttp/httpsys.cpp +++ b/src/zenhttp/httpsys.cpp @@ -32,7 +32,10 @@ namespace zen { /** * @brief Windows implementation of HTTP server based on http.sys * - * This requires elevation to function + * This requires elevation to function by default but system configuration + * can soften this requirement. + * + * See README.md for details. */ class HttpSysServer : public HttpServer { @@ -76,7 +79,8 @@ private: bool m_IsRequestLoggingEnabled = false; bool m_IsAsyncResponseEnabled = true; - WinIoThreadPool m_ThreadPool; + std::unique_ptr<WinIoThreadPool> m_IoThreadPool; + RwLock m_AsyncWorkPoolInitLock; WorkerThreadPool* m_AsyncWorkPool = nullptr; @@ -89,7 +93,7 @@ private: int32_t m_MinPendingRequests = 16; int32_t m_MaxPendingRequests = 128; Event m_ShutdownEvent; - const HttpSysConfig m_InitialConfig; + HttpSysConfig m_InitialConfig; }; } // namespace zen @@ -889,14 +893,45 @@ HttpAsyncWorkRequest::AsyncWorkItem::Execute() \/ \/ \/ */ -HttpSysServer::HttpSysServer(const HttpSysConfig& Config) +HttpSysServer::HttpSysServer(const HttpSysConfig& InConfig) : m_Log(logging::Get("http")) , m_RequestLog(logging::Get("http_requests")) -, m_IsRequestLoggingEnabled(Config.IsRequestLoggingEnabled) -, m_IsAsyncResponseEnabled(Config.IsAsyncResponseEnabled) -, m_ThreadPool(Config.ThreadCount != 0 ? Config.ThreadCount : std::thread::hardware_concurrency()) -, m_InitialConfig(Config) +, m_IsRequestLoggingEnabled(InConfig.IsRequestLoggingEnabled) +, m_IsAsyncResponseEnabled(InConfig.IsAsyncResponseEnabled) +, m_InitialConfig(InConfig) { + // Initialize thread pool + + int MinThreadCount; + int MaxThreadCount; + + if (m_InitialConfig.ThreadCount == 0) + { + MinThreadCount = Max(8u, std::thread::hardware_concurrency()); + } + else + { + MinThreadCount = m_InitialConfig.ThreadCount; + } + + MaxThreadCount = MinThreadCount * 2; + + if (m_InitialConfig.IsDedicatedServer) + { + // In order to limit the potential impact of threads stuck + // in locks we allow the thread pool to be oversubscribed + // by a fair amount + + MaxThreadCount *= 2; + } + + m_IoThreadPool = std::make_unique<WinIoThreadPool>(MinThreadCount, MaxThreadCount); + + if (m_InitialConfig.AsyncWorkThreadCount == 0) + { + m_InitialConfig.AsyncWorkThreadCount = 16; + } + ULONG Result = HttpInitialize(HTTPAPI_VERSION_2, HTTP_INITIALIZE_SERVER, nullptr); if (Result != NO_ERROR) @@ -907,7 +942,11 @@ HttpSysServer::HttpSysServer(const HttpSysConfig& Config) m_IsHttpInitialized = true; m_IsOk = true; - ZEN_INFO("http.sys server started, using {} I/O threads and {} async worker threads", Config.ThreadCount, Config.AsyncWorkThreadCount); + ZEN_INFO("http.sys server started in {} mode, using {}-{} I/O threads and {} async worker threads", + m_InitialConfig.IsDedicatedServer ? "DEDICATED" : "NORMAL", + MinThreadCount, + MaxThreadCount, + m_InitialConfig.AsyncWorkThreadCount); } HttpSysServer::~HttpSysServer() @@ -1070,10 +1109,27 @@ HttpSysServer::InitializeServer(int BasePort) 0); } + // Tune the maximum number of pending requests in the http.sys request queue. By default + // the value is 1000 which is plenty for single user machines but for dedicated servers + // serving many users it makes sense to increase this to a higher number to help smooth + // out intermittent stalls like we might experience when GC is triggered + + if (m_InitialConfig.IsDedicatedServer) + { + ULONG QueueLength = 50000; + + Result = HttpSetRequestQueueProperty(m_RequestQueueHandle, HttpServerQueueLengthProperty, &QueueLength, sizeof QueueLength, 0, 0); + + if (Result != NO_ERROR) + { + ZEN_WARN("changing request queue length to {} failed: {}", QueueLength, Result); + } + } + // Create I/O completion port std::error_code ErrorCode; - m_ThreadPool.CreateIocp(m_RequestQueueHandle, HttpSysTransaction::IoCompletionCallback, /* Context */ this, /* out */ ErrorCode); + m_IoThreadPool->CreateIocp(m_RequestQueueHandle, HttpSysTransaction::IoCompletionCallback, /* Context */ this, /* out */ ErrorCode); if (ErrorCode) { @@ -1137,9 +1193,7 @@ HttpSysServer::WorkPool() if (!m_AsyncWorkPool) { - unsigned int WorkerThreadCount = m_InitialConfig.AsyncWorkThreadCount != 0 ? m_InitialConfig.AsyncWorkThreadCount : 16; - - m_AsyncWorkPool = new WorkerThreadPool(WorkerThreadCount, "http_async"); + m_AsyncWorkPool = new WorkerThreadPool(m_InitialConfig.AsyncWorkThreadCount, "http_async"); } } @@ -1305,7 +1359,7 @@ HttpSysTransaction::~HttpSysTransaction() PTP_IO HttpSysTransaction::Iocp() { - return m_HttpServer.m_ThreadPool.Iocp(); + return m_HttpServer.m_IoThreadPool->Iocp(); } HANDLE diff --git a/src/zenhttp/httpsys.h b/src/zenhttp/httpsys.h index 1553d56ef..6a6b16525 100644 --- a/src/zenhttp/httpsys.h +++ b/src/zenhttp/httpsys.h @@ -20,6 +20,7 @@ struct HttpSysConfig unsigned int AsyncWorkThreadCount = 0; bool IsAsyncResponseEnabled = true; bool IsRequestLoggingEnabled = false; + bool IsDedicatedServer = false; }; Ref<HttpServer> CreateHttpSysServer(HttpSysConfig Config); diff --git a/src/zenhttp/include/zenhttp/httpserver.h b/src/zenhttp/include/zenhttp/httpserver.h index c233075be..3cbe05dd6 100644 --- a/src/zenhttp/include/zenhttp/httpserver.h +++ b/src/zenhttp/include/zenhttp/httpserver.h @@ -184,7 +184,8 @@ public: struct HttpServerConfig { - std::string ServerClass; // Choice of HTTP server implementation + bool IsDedicatedServer = false; // Should be set to true for shared servers + std::string ServerClass; // Choice of HTTP server implementation unsigned int ThreadCount = 0; struct diff --git a/src/zenhttp/iothreadpool.cpp b/src/zenhttp/iothreadpool.cpp index 6087e69ec..da4b42e28 100644 --- a/src/zenhttp/iothreadpool.cpp +++ b/src/zenhttp/iothreadpool.cpp @@ -8,14 +8,19 @@ namespace zen { -WinIoThreadPool::WinIoThreadPool(int InThreadCount) +WinIoThreadPool::WinIoThreadPool(int InThreadCount, int InMaxThreadCount) { - // Thread pool setup + ZEN_ASSERT(InThreadCount); + + if (InMaxThreadCount < InThreadCount) + { + InMaxThreadCount = InThreadCount; + } m_ThreadPool = CreateThreadpool(NULL); SetThreadpoolThreadMinimum(m_ThreadPool, InThreadCount); - SetThreadpoolThreadMaximum(m_ThreadPool, InThreadCount * 2); + SetThreadpoolThreadMaximum(m_ThreadPool, InMaxThreadCount); InitializeThreadpoolEnvironment(&m_CallbackEnvironment); diff --git a/src/zenhttp/iothreadpool.h b/src/zenhttp/iothreadpool.h index 8333964c3..e75e95e58 100644 --- a/src/zenhttp/iothreadpool.h +++ b/src/zenhttp/iothreadpool.h @@ -11,16 +11,10 @@ namespace zen { -////////////////////////////////////////////////////////////////////////// -// -// Thread pool. Implemented in terms of Windows thread pool right now, will -// need a cross-platform implementation eventually -// - class WinIoThreadPool { public: - WinIoThreadPool(int InThreadCount); + WinIoThreadPool(int InThreadCount, int InMaxThreadCount); ~WinIoThreadPool(); void CreateIocp(HANDLE IoHandle, PTP_WIN32_IO_CALLBACK Callback, void* Context, std::error_code& ErrorCode); diff --git a/src/zenhttp/xmake.lua b/src/zenhttp/xmake.lua index 9c3869911..588fd8b87 100644 --- a/src/zenhttp/xmake.lua +++ b/src/zenhttp/xmake.lua @@ -7,7 +7,7 @@ target('zenhttp') add_files("**.cpp") add_files("httpsys.cpp", {unity_ignored=true}) add_includedirs("include", {public=true}) - add_deps("zencore", "plugins") + add_deps("zencore", "transport-sdk") add_packages( "vcpkg::cpr", "vcpkg::curl", -- required by cpr diff --git a/src/zenserver/config.cpp b/src/zenserver/config.cpp index 319bcdafb..9112222d6 100644 --- a/src/zenserver/config.cpp +++ b/src/zenserver/config.cpp @@ -1353,6 +1353,8 @@ ParseCliOptions(int argc, char* argv[], ZenServerOptions& ServerOptions) { ServerOptions.AbsLogFile = ServerOptions.DataDir / "logs" / "zenserver.log"; } + + ServerOptions.HttpServerConfig.IsDedicatedServer = ServerOptions.IsDedicated; } } // namespace zen diff --git a/src/zenstore/gc.cpp b/src/zenstore/gc.cpp index bddc3a42a..0f3f178d6 100644 --- a/src/zenstore/gc.cpp +++ b/src/zenstore/gc.cpp @@ -793,7 +793,7 @@ GcScheduler::SchedulerThread() bool DoDelete = true; bool CollectSmallObjects = m_Config.CollectSmallObjects; std::chrono::seconds GcInterval = m_Config.Interval; - std::chrono::seconds LightwightGcInterval = m_Config.LightweightInterval; + std::chrono::seconds LightweightGcInterval = m_Config.LightweightInterval; std::chrono::seconds MaxCacheDuration = m_Config.MaxCacheDuration; std::chrono::seconds MaxProjectStoreDuration = m_Config.MaxProjectStoreDuration; uint64_t DiskSizeSoftLimit = m_Config.DiskSizeSoftLimit; @@ -914,38 +914,48 @@ GcScheduler::SchedulerThread() } } - std::chrono::seconds RemaingTimeUntilGc = + std::chrono::seconds RemainingTimeUntilGc = GcInterval.count() == 0 ? std::chrono::seconds::max() : std::chrono::duration_cast<std::chrono::seconds>(m_LastGcTime + GcInterval - GcClock::Now()); - if (RemaingTimeUntilGc < std::chrono::seconds::zero()) + + if (RemainingTimeUntilGc < std::chrono::seconds::zero()) + { + RemainingTimeUntilGc = std::chrono::seconds::zero(); + } + + std::chrono::seconds RemainingTimeUntilLightweightGc = + LightweightGcInterval.count() == 0 ? std::chrono::seconds::max() + : std::chrono::duration_cast<std::chrono::seconds>( + m_LastLightweightGcTime + LightweightGcInterval - GcClock::Now()); + + if (RemainingTimeUntilLightweightGc < std::chrono::seconds::zero()) { - RemaingTimeUntilGc = std::chrono::seconds::zero(); + RemainingTimeUntilLightweightGc = std::chrono::seconds::zero(); } - std::chrono::seconds RemaingTimeUntilLightweightGc = - LightwightGcInterval.count() == 0 - ? std::chrono::seconds::max() - : std::chrono::duration_cast<std::chrono::seconds>(m_LastLightweightGcTime + LightwightGcInterval - GcClock::Now()); - if (RemaingTimeUntilLightweightGc < std::chrono::seconds::zero()) + + // Don't schedule a lightweight GC if a full GC is + // due quite soon anyway + if (RemainingTimeUntilGc < LightweightGcInterval) { - RemaingTimeUntilLightweightGc = std::chrono::seconds::zero(); + RemainingTimeUntilLightweightGc = RemainingTimeUntilGc; } if (GcDiskSpaceGoal > 0) { DiskSpaceGCTriggered = true; } - else if (RemaingTimeUntilGc.count() == 0) + else if (RemainingTimeUntilGc.count() == 0) { TimeBasedGCTriggered = true; } - else if (RemaingTimeUntilLightweightGc.count() == 0) + else if (RemainingTimeUntilLightweightGc.count() == 0) { TimeBasedGCTriggered = true; SkipCid = true; } std::string NextTriggerStatus; - if (GcInterval.count() != 0 || LightwightGcInterval.count() != 0 || DiskSizeSoftLimit != 0) + if (GcInterval.count() != 0 || LightweightGcInterval.count() != 0 || DiskSizeSoftLimit != 0) { ExtendableStringBuilder<256> Sb; if (DiskSpaceGCTriggered) @@ -970,13 +980,13 @@ GcScheduler::SchedulerThread() if (GcInterval.count() != 0) { Sb.Append(fmt::format(" Full GC in {}.", - NiceTimeSpanMs(uint64_t(std::chrono::milliseconds(RemaingTimeUntilGc).count())))); + NiceTimeSpanMs(uint64_t(std::chrono::milliseconds(RemainingTimeUntilGc).count())))); } - if (LightwightGcInterval.count() != 0) + if (LightweightGcInterval.count() != 0) { Sb.Append( fmt::format(" Lightweight GC in {}.", - NiceTimeSpanMs(uint64_t(std::chrono::milliseconds(RemaingTimeUntilLightweightGc).count())))); + NiceTimeSpanMs(uint64_t(std::chrono::milliseconds(RemainingTimeUntilLightweightGc).count())))); } if (DiskSizeSoftLimit != 0 && DiskSizeSoftLimit > TotalSize.DiskSize) { @@ -1002,13 +1012,13 @@ GcScheduler::SchedulerThread() if (!DiskSpaceGCTriggered && !TimeBasedGCTriggered) { WaitTime = m_Config.MonitorInterval; - if (RemaingTimeUntilGc < WaitTime) + if (RemainingTimeUntilGc < WaitTime) { - WaitTime = RemaingTimeUntilGc; + WaitTime = RemainingTimeUntilGc; } - if (RemaingTimeUntilLightweightGc < WaitTime) + if (RemainingTimeUntilLightweightGc < WaitTime) { - WaitTime = RemaingTimeUntilLightweightGc; + WaitTime = RemainingTimeUntilLightweightGc; } continue; } diff --git a/src/zenutil/include/zenutil/logging.h b/src/zenutil/include/zenutil/logging.h new file mode 100644 index 000000000..6f408f512 --- /dev/null +++ b/src/zenutil/include/zenutil/logging.h @@ -0,0 +1,33 @@ +// Copyright Epic Games, Inc. All Rights Reserved. + +#pragma once + +#include <zencore/logging.h> + +#include <filesystem> +#include <string> + +////////////////////////////////////////////////////////////////////////// +// +// Logging utilities +// +// These functions extend the basic logging functionality by setting up +// console and file logging, as well as colored output where available, +// for sharing across different executables +// + +namespace zen { + +struct LoggingOptions +{ + bool IsDebug = false; + bool IsVerbose = false; + bool IsTest = false; + std::filesystem::path AbsLogFile; // Absolute path to main log file + std::string LogId; +}; + +void InitializeLogging(const LoggingOptions& LoggingOptions); +void ShutdownLogging(); + +} // namespace zen diff --git a/src/zenutil/logging.cpp b/src/zenutil/logging.cpp new file mode 100644 index 000000000..c0a63cc71 --- /dev/null +++ b/src/zenutil/logging.cpp @@ -0,0 +1,516 @@ +// 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 <spdlog/async.h> +#include <spdlog/async_logger.h> +#include <spdlog/pattern_formatter.h> +#include <spdlog/sinks/ansicolor_sink.h> +#include <spdlog/sinks/basic_file_sink.h> +#include <spdlog/sinks/daily_file_sink.h> +#include <spdlog/sinks/msvc_sink.h> +#include <spdlog/sinks/rotating_file_sink.h> +#include <spdlog/sinks/stdout_color_sinks.h> +#if ZEN_USE_SENTRY +# include <sentry.h> +#endif +ZEN_THIRD_PARTY_INCLUDES_END + +#include <zencore/filesystem.h> +#include <zencore/string.h> + +#include <chrono> +#include <memory> + +// 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<std::chrono::system_clock> Epoch) : m_Epoch(Epoch), m_LogId(LogId) {} + + virtual std::unique_ptr<formatter> clone() const override { return std::make_unique<full_formatter>(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<seconds>(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<seconds>(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<milliseconds>(msg.time); + fmt_helper::pad3(static_cast<uint32_t>(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<details::null_scoped_padder>::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<std::chrono::system_clock> 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<formatter> clone() const override { return std::make_unique<json_formatter>(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<seconds>(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<milliseconds>(msg.time); + fmt_helper::pad3(static_cast<uint32_t>(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<details::null_scoped_padder>::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<char, std::string_view> 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<spdlog::details::null_mutex> +{ +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<spdlog::sinks::ansicolor_stdout_sink_mt>("main"); + zen::logging::SetDefault(AsyncLogger); + } + + // Sinks + + auto ConsoleSink = std::make_shared<spdlog::sinks::ansicolor_stdout_sink_mt>(); + + 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<spdlog::sinks::daily_file_sink_mt>( zen::PathToUtf8(GlobalOptions.AbsLogFile), + 0, + 0, + /* truncate */ false, + uint16_t(/* max files */ 14)); +#else + FileSink = std::make_shared<spdlog::sinks::rotating_file_sink_mt>(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<sentry_sink>(); +#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<spdlog::sinks::msvc_sink_mt>(); + 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<logging::full_formatter>(LogOptions.LogId, std::chrono::system_clock::now())); + + if (FileSink) + { + if (LogOptions.AbsLogFile.extension() == ".json") + { + FileSink->set_formatter(std::make_unique<logging::json_formatter>(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 |