log.cpp 9.7 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252
  1. #include "log.h"
  2. #include <Windows.h>
  3. #include <array>
  4. #include <atomic>
  5. #include <cstdio>
  6. #include <cstring>
  7. #include "../filesystem/path.h"
  8. #include "snapshot/internal.h"
  9. namespace sunrise::core::log {
  10. namespace {
  11. /** Stable serialized channel names ordered by Channel. */
  12. constexpr std::array<std::string_view, static_cast<std::size_t>(Channel::count)> kChannelNames{
  13. "core", "client", "state", "server", "middleware"};
  14. /** Stable serialized severity names; Level::off is never emitted. */
  15. constexpr std::array<std::string_view, 4> kLevelNames{"error", "warn", "info", "debug"};
  16. /** Optional logs are isolated below the shared generated-artifact directory. */
  17. constexpr std::wstring_view kLogDirectorySuffix = L"\\logs";
  18. /** The active log keeps one stable filename across process starts. */
  19. constexpr std::wstring_view kLogFileSuffix = L"\\sunrise.log";
  20. /** Rotation keeps exactly one prior startup log beside the active file. */
  21. constexpr std::wstring_view kPreviousLogSuffix = L".old";
  22. /** CRLF ends every emitted Windows log record. */
  23. constexpr std::string_view kLineEnding = "\r\n";
  24. /** One trailing null byte is kept for the debugger sink. */
  25. constexpr std::size_t kLineTerminatorBytes = 1;
  26. /** Event text stops before the CRLF and the trailing null. */
  27. constexpr std::size_t kEventTextCapacity =
  28. kLineCapacity - kLineEnding.size() - kLineTerminatorBytes;
  29. /** Longest " t=" field: the key plus a 64-bit millisecond count. */
  30. constexpr std::size_t kStampCapacity = 32;
  31. struct LogState {
  32. SRWLOCK lock{SRWLOCK_INIT};
  33. std::array<std::atomic<Level>, static_cast<std::size_t>(Channel::count)> levels{};
  34. HANDLE file{INVALID_HANDLE_VALUE};
  35. /** Tick the sinks opened on. Every line carries its offset from this, so stalls are visible. */
  36. ULONGLONG startTick{};
  37. bool debuggerSink{};
  38. bool initialized{};
  39. };
  40. LogState g_log;
  41. /** Threads inside a sink write. Read by anything that suspends process threads. */
  42. std::atomic_int g_writers{};
  43. /**
  44. * Tests one event against its channel threshold.
  45. * @param channel Channel that owns the event.
  46. * @param level Event severity.
  47. * @return True when a valid channel threshold permits the event level.
  48. */
  49. [[nodiscard]] bool enabled(Channel channel, Level level) noexcept {
  50. const auto index = static_cast<std::size_t>(channel);
  51. if (index >= g_log.levels.size() || level == Level::off) {
  52. return false;
  53. }
  54. return static_cast<unsigned char>(level)
  55. <= static_cast<unsigned char>(g_log.levels[index].load(std::memory_order_relaxed));
  56. }
  57. /**
  58. * Appends as much text as fits before one caller-provided content boundary.
  59. * @param line Fixed event-line storage.
  60. * @param offset First free byte.
  61. * @param text Text to append.
  62. * @param limit Exclusive content boundary reserved by the caller.
  63. * @return New first-free byte offset.
  64. */
  65. [[nodiscard]] std::size_t append(std::array<char, kLineCapacity>& line,
  66. std::size_t offset,
  67. std::string_view text,
  68. std::size_t limit) noexcept {
  69. const std::size_t available = offset < limit ? limit - offset : 0;
  70. const std::size_t count = text.size() < available ? text.size() : available;
  71. if (count != 0) {
  72. std::memcpy(line.data() + offset, text.data(), count);
  73. }
  74. return offset + count;
  75. }
  76. /**
  77. * Rotates one prior log and opens a new file below the owned artifact directory.
  78. * @param module Loaded DLL module used to resolve the log directory.
  79. * @return Writable file handle, or INVALID_HANDLE_VALUE on failure.
  80. */
  81. [[nodiscard]] HANDLE open_log_file(void* module) noexcept {
  82. path::Buffer logPath;
  83. if (!path::artifact_directory(module, logPath) || !path::append(logPath, kLogDirectorySuffix)) {
  84. return INVALID_HANDLE_VALUE;
  85. }
  86. if (!CreateDirectoryW(logPath.chars.data(), nullptr)
  87. && GetLastError() != ERROR_ALREADY_EXISTS) {
  88. return INVALID_HANDLE_VALUE;
  89. }
  90. if (!path::append(logPath, kLogFileSuffix)) {
  91. return INVALID_HANDLE_VALUE;
  92. }
  93. path::Buffer oldPath = logPath;
  94. if (!path::append(oldPath, kPreviousLogSuffix)) {
  95. return INVALID_HANDLE_VALUE;
  96. }
  97. // Rotation intentionally keeps only one previous file.
  98. MoveFileExW(logPath.chars.data(), oldPath.chars.data(), MOVEFILE_REPLACE_EXISTING);
  99. return CreateFileW(logPath.chars.data(),
  100. GENERIC_WRITE,
  101. FILE_SHARE_READ,
  102. nullptr,
  103. CREATE_ALWAYS,
  104. FILE_ATTRIBUTE_NORMAL,
  105. nullptr);
  106. }
  107. } // namespace
  108. /** @return Default warning thresholds with debugger output enabled. */
  109. Settings defaults() noexcept {
  110. Settings settings;
  111. settings.levels.fill(Level::warn);
  112. return settings;
  113. }
  114. /** Applies log thresholds and opens the optional file sink. */
  115. bool initialize(void* module, const Settings& settings) noexcept {
  116. AcquireSRWLockExclusive(&g_log.lock);
  117. // Resetting under the lifetime lock prevents an admitted writer from repopulating stale view.
  118. snapshot::internal::reset();
  119. if (g_log.file != INVALID_HANDLE_VALUE) {
  120. CloseHandle(g_log.file);
  121. g_log.file = INVALID_HANDLE_VALUE;
  122. }
  123. g_log.initialized = false;
  124. g_log.debuggerSink = settings.debuggerSink;
  125. g_log.startTick = GetTickCount64();
  126. for (std::size_t index = 0; index < g_log.levels.size(); ++index) {
  127. g_log.levels[index].store(settings.levels[index], std::memory_order_relaxed);
  128. }
  129. if (settings.fileSink) {
  130. g_log.file = open_log_file(module);
  131. }
  132. const bool ready = !settings.fileSink || g_log.file != INVALID_HANDLE_VALUE;
  133. g_log.initialized = ready;
  134. if (!ready) {
  135. g_log.debuggerSink = false;
  136. for (std::atomic<Level>& level : g_log.levels) {
  137. level.store(Level::off, std::memory_order_relaxed);
  138. }
  139. }
  140. ReleaseSRWLockExclusive(&g_log.lock);
  141. return ready;
  142. }
  143. /** Closes the optional sink and clears the bounded in-memory view. */
  144. void shutdown() noexcept {
  145. AcquireSRWLockExclusive(&g_log.lock);
  146. g_log.initialized = false;
  147. for (std::atomic<Level>& level : g_log.levels) {
  148. level.store(Level::off, std::memory_order_relaxed);
  149. }
  150. g_log.debuggerSink = false;
  151. if (g_log.file != INVALID_HANDLE_VALUE) {
  152. CloseHandle(g_log.file);
  153. g_log.file = INVALID_HANDLE_VALUE;
  154. }
  155. // The same lifetime lock excludes writers until both sinks and retained entries are empty.
  156. snapshot::internal::reset();
  157. ReleaseSRWLockExclusive(&g_log.lock);
  158. }
  159. /** Writes one line straight to the debugger, bypassing the sinks and every threshold. */
  160. void early(std::string_view event) noexcept {
  161. std::array<char, kLineCapacity> line{};
  162. std::size_t length = append(line, 0, "core level=error ", kEventTextCapacity);
  163. length = append(line, length, event, kEventTextCapacity);
  164. std::memcpy(line.data() + length, kLineEnding.data(), kLineEnding.size());
  165. line[length + kLineEnding.size()] = '\0';
  166. g_writers.fetch_add(1, std::memory_order_acq_rel);
  167. OutputDebugStringA(line.data());
  168. g_writers.fetch_sub(1, std::memory_order_acq_rel);
  169. }
  170. /** Reports whether an event would be emitted, so callers can skip the cost of building one. */
  171. bool accepts(Channel channel, Level level) noexcept {
  172. AcquireSRWLockShared(&g_log.lock);
  173. const bool admitted = g_log.initialized && enabled(channel, level);
  174. ReleaseSRWLockShared(&g_log.lock);
  175. return admitted;
  176. }
  177. /** Formats and emits one bounded structured event. */
  178. void write(Channel channel, Level level, std::string_view event) noexcept {
  179. const auto channelIndex = static_cast<std::size_t>(channel);
  180. const auto levelIndex = static_cast<std::size_t>(level);
  181. if (channelIndex >= kChannelNames.size() || levelIndex >= kLevelNames.size()) {
  182. return;
  183. }
  184. AcquireSRWLockShared(&g_log.lock);
  185. if (!g_log.initialized || !enabled(channel, level)) {
  186. ReleaseSRWLockShared(&g_log.lock);
  187. return;
  188. }
  189. std::array<char, kStampCapacity> stamp{};
  190. const int stamped =
  191. std::snprintf(stamp.data(),
  192. stamp.size(),
  193. " t=%llu ",
  194. static_cast<unsigned long long>(GetTickCount64() - g_log.startTick));
  195. std::array<char, kLineCapacity> line{};
  196. std::size_t length = append(line, 0, kChannelNames[channelIndex], kEventTextCapacity);
  197. length = append(line, length, " level=", kEventTextCapacity);
  198. length = append(line, length, kLevelNames[levelIndex], kEventTextCapacity);
  199. length = append(line,
  200. length,
  201. stamped > 0 ? std::string_view(stamp.data(), static_cast<std::size_t>(stamped))
  202. : std::string_view(" "),
  203. kEventTextCapacity);
  204. length = append(line, length, event, kEventTextCapacity);
  205. const std::size_t snapshotLength = length;
  206. std::memcpy(line.data() + length, kLineEnding.data(), kLineEnding.size());
  207. length += kLineEnding.size();
  208. line[length] = '\0';
  209. // The admission lock stays held across the sinks and the snapshot record.
  210. g_writers.fetch_add(1, std::memory_order_acq_rel);
  211. if (g_log.debuggerSink) {
  212. OutputDebugStringA(line.data());
  213. }
  214. if (g_log.file != INVALID_HANDLE_VALUE) {
  215. DWORD written = 0;
  216. WriteFile(g_log.file, line.data(), static_cast<DWORD>(length), &written, nullptr);
  217. }
  218. g_writers.fetch_sub(1, std::memory_order_acq_rel);
  219. // Record after sink writes while the shared lifetime lock still excludes shutdown reset.
  220. snapshot::internal::record(channel, level, std::string_view(line.data(), snapshotLength));
  221. ReleaseSRWLockShared(&g_log.lock);
  222. }
  223. /** @return True while a sink write is in progress. */
  224. bool writers_active() noexcept {
  225. return g_writers.load(std::memory_order_acquire) != 0;
  226. }
  227. } // namespace sunrise::core::log