From 7f2885b54e173e80a3df4b5d7f62c4fadc739945 Mon Sep 17 00:00:00 2001 From: AR-DEV-1 Date: Wed, 17 Jun 2026 16:43:45 +0500 Subject: [PATCH 1/5] Add the logging system --- Engine/cpp/runtime/CMakeLists.txt | 2 +- Engine/cpp/runtime/core/CMakeLists.txt | 2 + Engine/cpp/runtime/core/core.cppm | 1 + Engine/cpp/runtime/core/io/image_loader.cpp | 2 +- Engine/cpp/runtime/core/logging/logging.cpp | 477 ++++++++++++++++++ Engine/cpp/runtime/core/logging/logging.cppm | 168 ++++++ .../cpp/runtime/core/logging/logging.test.cpp | 369 ++++++++++++++ Engine/cpp/runtime/core/logging/macros.h | 19 + 8 files changed, 1038 insertions(+), 2 deletions(-) create mode 100644 Engine/cpp/runtime/core/logging/logging.cpp create mode 100644 Engine/cpp/runtime/core/logging/logging.cppm create mode 100644 Engine/cpp/runtime/core/logging/logging.test.cpp create mode 100644 Engine/cpp/runtime/core/logging/macros.h diff --git a/Engine/cpp/runtime/CMakeLists.txt b/Engine/cpp/runtime/CMakeLists.txt index c9f083ed..74b0ae9b 100644 --- a/Engine/cpp/runtime/CMakeLists.txt +++ b/Engine/cpp/runtime/CMakeLists.txt @@ -5,7 +5,7 @@ add_modules_library(rendering) add_modules_library(scene) target_link_libraries(platform PUBLIC platform_impl) -target_link_libraries(core PUBLIC definitions math io memory) +target_link_libraries(core PUBLIC definitions math io memory logging) target_link_libraries(input PRIVATE SDL3::SDL3-static platform core) target_link_libraries(rendering PUBLIC rhi rendergraph mesh material quad_renderer renderer) target_link_libraries(scene PUBLIC renderable transform_component camera) diff --git a/Engine/cpp/runtime/core/CMakeLists.txt b/Engine/cpp/runtime/core/CMakeLists.txt index dd4dfb1b..9925bc42 100644 --- a/Engine/cpp/runtime/core/CMakeLists.txt +++ b/Engine/cpp/runtime/core/CMakeLists.txt @@ -2,7 +2,9 @@ add_modules_library(definitions PIC) add_modules_library(math) add_modules_library(io) add_modules_library(memory) +add_modules_library(logging) target_link_libraries(math PUBLIC definitions bx) target_link_libraries(io PUBLIC definitions stb_image) target_link_libraries(memory PUBLIC definitions math) +target_link_libraries(logging PUBLIC definitions) \ No newline at end of file diff --git a/Engine/cpp/runtime/core/core.cppm b/Engine/cpp/runtime/core/core.cppm index 9de09a0a..a8fe8205 100644 --- a/Engine/cpp/runtime/core/core.cppm +++ b/Engine/cpp/runtime/core/core.cppm @@ -3,3 +3,4 @@ export import core.defs; export import core.math; export import core.memory; export import core.io; +export import core.logging; diff --git a/Engine/cpp/runtime/core/io/image_loader.cpp b/Engine/cpp/runtime/core/io/image_loader.cpp index 98ec0b44..93a95970 100644 --- a/Engine/cpp/runtime/core/io/image_loader.cpp +++ b/Engine/cpp/runtime/core/io/image_loader.cpp @@ -12,7 +12,7 @@ module core.io.image_loader; import core.stdtypes; -// TODO: I'm too lazy to write code so we need somethin' better +// TODO: I'm too lazy to write code so we need somethin' better (AR-DEV-1) namespace draco::core::io::image_loader { diff --git a/Engine/cpp/runtime/core/logging/logging.cpp b/Engine/cpp/runtime/core/logging/logging.cpp new file mode 100644 index 00000000..2211e06a --- /dev/null +++ b/Engine/cpp/runtime/core/logging/logging.cpp @@ -0,0 +1,477 @@ +module; + +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include "macros.h" + +module core.logging; + +import core.stdtypes; + +namespace draco::core::logging +{ + static constexpr usize QUEUE_CAPACITY = 8192; + static constexpr usize QUEUE_MASK = QUEUE_CAPACITY - 1; + + struct Node + { + std::atomic sequence; + LogMessage msg; + }; + + alignas(64) static Node g_queue[QUEUE_CAPACITY]; + alignas(64) static std::atomic g_enqueue_pos{0}; + alignas(64) static std::atomic g_dequeue_pos{0}; + alignas(64) static std::atomic g_dispatched_pos{0}; + + static std::atomic g_dropped_count{0}; + static std::atomic g_written_count{0}; + + static std::atomic g_running{false}; + static std::atomic g_accepting_logs{false}; + static std::atomic g_active_producers{0}; + + static std::thread g_worker_thread; + static std::mutex g_worker_mutex; + static std::condition_variable g_worker_cv; + + static std::atomic g_global_verbosity{LogVerbosity::Info}; + + struct SinkList + { + std::vector> sinks; + }; + + static std::atomic> g_sink_list{ nullptr }; + static std::mutex g_sink_update_mutex; + + static std::chrono::steady_clock::time_point g_start_time; + + namespace internal + { + void (*fatal_hook)() = []() { std::abort(); }; + } + + static u32 get_thread_id() + { + return static_cast(std::hash{}(std::this_thread::get_id())); + } + + static u64 uptime_ns() + { + return std::chrono::duration_cast(std::chrono::steady_clock::now() - g_start_time).count(); + } + + static const char* verbosity_to_string(LogVerbosity v) + { + switch (v) + { + case LogVerbosity::Fatal: return "FATAL"; + case LogVerbosity::Error: return "ERROR"; + case LogVerbosity::Warning: return "WARNING"; + case LogVerbosity::Display: return "DISPLAY"; + case LogVerbosity::Info: return "INFO"; + case LogVerbosity::Verbose: return "VERBOSE"; + case LogVerbosity::VeryVerbose: return "VERYVERBOSE"; + } + return "UNKNOWN"; + } + + static void enqueue(const LogMessage& msg) + { + usize pos = g_enqueue_pos.load(std::memory_order_relaxed); + while (true) + { + Node* node = &g_queue[pos & QUEUE_MASK]; + usize seq = node->sequence.load(std::memory_order_acquire); + intptr_t diff = static_cast(seq) - static_cast(pos); + + if (diff == 0) + { + if (g_enqueue_pos.compare_exchange_weak(pos, pos + 1, std::memory_order_relaxed)) + { + node->msg = msg; + node->msg.sequence_id = pos; + + bool was_empty = (pos == g_dequeue_pos.load(std::memory_order_relaxed)); + + node->sequence.store(pos + 1, std::memory_order_release); + + if (was_empty) + { + std::lock_guard lock(g_worker_mutex); + g_worker_cv.notify_one(); + } + return; + } + } + else if (diff < 0) + { + g_dropped_count.fetch_add(1, std::memory_order_relaxed); + return; + } + else + { + pos = g_enqueue_pos.load(std::memory_order_relaxed); + } + } + } + + static bool dequeue(LogMessage& msg) + { + usize pos = g_dequeue_pos.load(std::memory_order_relaxed); + Node* node = &g_queue[pos & QUEUE_MASK]; + usize seq = node->sequence.load(std::memory_order_acquire); + intptr_t diff = static_cast(seq) - static_cast(pos + 1); + + if (diff == 0) + { + msg = node->msg; + g_dequeue_pos.store(pos + 1, std::memory_order_relaxed); + node->sequence.store(pos + QUEUE_CAPACITY, std::memory_order_release); + return true; + } + return false; + } + + static void worker_loop() + { + while (true) + { + bool running = g_running.load(std::memory_order_acquire); + std::shared_ptr current_sinks = g_sink_list.load(std::memory_order_acquire); + + LogMessage msg; + bool popped = false; + + while (dequeue(msg)) + { + if (current_sinks) + { + for (auto& sink : current_sinks->sinks) + { + if (sink) sink->write(msg); + } + } + g_written_count.fetch_add(1, std::memory_order_relaxed); + g_dispatched_pos.store(g_dequeue_pos.load(std::memory_order_relaxed), std::memory_order_release); + popped = true; + } + + if (!running && !popped) + { + if (g_dequeue_pos.load(std::memory_order_relaxed) == g_enqueue_pos.load(std::memory_order_acquire)) + { + break; + } + } + + if (!popped) + { + std::unique_lock lock(g_worker_mutex); + if (!g_running.load(std::memory_order_acquire)) continue; + if (g_dequeue_pos.load(std::memory_order_relaxed) != g_enqueue_pos.load(std::memory_order_acquire)) continue; + + g_worker_cv.wait_for(lock, std::chrono::milliseconds(2)); + } + } + } + + void init() + { + g_start_time = std::chrono::steady_clock::now(); + g_global_verbosity.store(LogVerbosity::Info); + g_dropped_count.store(0); + g_written_count.store(0); + g_active_producers.store(0); + + for (usize i = 0; i < QUEUE_CAPACITY; i++) + { + g_queue[i].sequence.store(i, std::memory_order_relaxed); + } + g_enqueue_pos.store(0); + g_dequeue_pos.store(0); + g_dispatched_pos.store(0); + + { + std::lock_guard lock(g_sink_update_mutex); + g_sink_list.store(std::make_shared(), std::memory_order_release); + } + + g_accepting_logs.store(true, std::memory_order_release); + g_running.store(true, std::memory_order_release); + g_worker_thread = std::thread(worker_loop); + } + + void shutdown() + { + if (g_accepting_logs.exchange(false, std::memory_order_release)) + { + while (g_active_producers.load(std::memory_order_acquire) > 0) + { + std::this_thread::yield(); + } + + flush(); + + g_running.store(false, std::memory_order_release); + { + std::lock_guard lock(g_worker_mutex); + g_worker_cv.notify_all(); + } + if (g_worker_thread.joinable()) + { + g_worker_thread.join(); + } + + std::lock_guard lock(g_sink_update_mutex); + g_sink_list.store(nullptr, std::memory_order_release); + } + } + + void flush() + { + usize target = g_enqueue_pos.load(std::memory_order_acquire); + while (g_dispatched_pos.load(std::memory_order_acquire) < target) + { + std::this_thread::yield(); + } + + std::shared_ptr current_sinks = g_sink_list.load(std::memory_order_acquire); + if (current_sinks) + { + for (auto& sink : current_sinks->sinks) + { + if (sink) sink->flush(); + } + } + } + + void set_global_verbosity(LogVerbosity v) + { + g_global_verbosity.store(v); + } + + void add_sink(std::shared_ptr sink) + { + if (!sink) return; + std::lock_guard lock(g_sink_update_mutex); + auto current = g_sink_list.load(std::memory_order_acquire); + auto next = std::make_shared(); + if (current) + { + next->sinks = current->sinks; + } + if (std::find(next->sinks.begin(), next->sinks.end(), sink) == next->sinks.end()) + { + next->sinks.push_back(sink); + } + g_sink_list.store(next, std::memory_order_release); + } + + void remove_sink(std::shared_ptr sink) + { + if (!sink) return; + std::lock_guard lock(g_sink_update_mutex); + auto current = g_sink_list.load(std::memory_order_acquire); + auto next = std::make_shared(); + if (current) + { + next->sinks = current->sinks; + } + auto it = std::find(next->sinks.begin(), next->sinks.end(), sink); + if (it != next->sinks.end()) + { + next->sinks.erase(it); + } + g_sink_list.store(next, std::memory_order_release); + } + + void log(LogVerbosity verbosity, const LogCategory& category, const char* file, const char* function, u32 line, const char* text) + { + if (!g_accepting_logs.load(std::memory_order_acquire)) return; + + g_active_producers.fetch_add(1, std::memory_order_acquire); + if (!g_accepting_logs.load(std::memory_order_acquire)) + { + g_active_producers.fetch_sub(1, std::memory_order_release); + return; + } + + LogVerbosity target_verbosity = g_global_verbosity.load(std::memory_order_relaxed); + i32 category_override = category.override_verbosity.load(std::memory_order_relaxed); + if (category_override >= 0) + { + target_verbosity = static_cast(category_override); + } + + if (verbosity <= target_verbosity) + { + LogMessage msg{}; + msg.uptime_ns = uptime_ns(); + msg.thread_id = get_thread_id(); + msg.verbosity = verbosity; + msg.category = &category; + msg.file = file; + msg.function = function; + msg.line = line; + + std::strncpy(msg.text, text, MaxLogMessageLength - 1); + msg.text[MaxLogMessageLength - 1] = '\0'; + + enqueue(msg); + } + + g_active_producers.fetch_sub(1, std::memory_order_release); + } + + [[noreturn]] + void fatal(const LogCategory& category, const char* file, const char* function, u32 line, const char* text) + { + LogMessage msg{}; + msg.uptime_ns = uptime_ns(); + msg.thread_id = get_thread_id(); + msg.verbosity = LogVerbosity::Fatal; + msg.category = &category; + msg.file = file; + msg.function = function; + msg.line = line; + + std::strncpy(msg.text, text, MaxLogMessageLength - 1); + msg.text[MaxLogMessageLength - 1] = '\0'; + + f64 uptime_s = static_cast(msg.uptime_ns) / 1'000'000'000.0; + std::println("[FATAL] [{:.6f}] [{}]: {}", uptime_s, category.name, msg.text); + + std::shared_ptr current_sinks = g_sink_list.load(std::memory_order_acquire); + if (current_sinks) + { + for (auto& sink : current_sinks->sinks) + { + if (sink) + { + sink->write(msg); + sink->flush(); + } + } + } + + internal::fatal_hook(); + std::abort(); + } + + LoggerMetrics get_metrics() + { + LoggerMetrics m{}; + m.messages_written = g_written_count.load(std::memory_order_relaxed); + m.messages_dropped = g_dropped_count.load(std::memory_order_relaxed); + + usize ep = g_enqueue_pos.load(std::memory_order_relaxed); + usize dp = g_dequeue_pos.load(std::memory_order_relaxed); + m.queue_depth = (ep >= dp) ? (ep - dp) : 0; + + auto current = g_sink_list.load(std::memory_order_acquire); + m.active_sinks = current ? static_cast(current->sinks.size()) : 0; + m.uptime_ns = uptime_ns(); + return m; + } + + void ConsoleSink::write(const LogMessage& msg) + { + f64 uptime_s = static_cast(msg.uptime_ns) / 1'000'000'000.0; + std::println("[{}] [{:.6f}] [{}] {}", verbosity_to_string(msg.verbosity), uptime_s, msg.category->name, msg.text); + } + + void ConsoleSink::flush() + { + std::fflush(stdout); + } + + FileSink::FileSink(const std::filesystem::path& path) + { + m_stream.open(path, std::ios::out | std::ios::app); + } + + void FileSink::write(const LogMessage& msg) + { + if (m_stream.is_open()) + { + m_stream << "[" << verbosity_to_string(msg.verbosity) << "] [" << msg.category->name << "] " << msg.text << "\n"; + } + } + + void FileSink::flush() + { + if (m_stream.is_open()) + { + m_stream.flush(); + } + } + + RollingFileSink::RollingFileSink(const std::filesystem::path& base_path, usize max_file_size) : m_base_path(base_path), m_max_file_size(max_file_size) + { + roll_file(); + } + + void RollingFileSink::roll_file() + { + if (m_stream.is_open()) m_stream.close(); + + auto now = std::chrono::system_clock::now(); + auto time = std::chrono::system_clock::to_time_t(now); + std::tm tm_buf{}; +#if defined(_WIN32) + localtime_s(&tm_buf, &time); +#else + localtime_r(&time, &tm_buf); +#endif + std::stringstream ss; + ss << std::put_time(&tm_buf, "%Y%m%d_%H%M%S"); + + std::string ext = m_base_path.extension().string(); + std::string stem = m_base_path.stem().string(); + auto parent = m_base_path.parent_path(); + + std::filesystem::path new_path = parent / (stem + "_" + ss.str() + ext); + m_stream.open(new_path, std::ios::out | std::ios::trunc); + m_current_size = 0; + } + + void RollingFileSink::write(const LogMessage& msg) + { + if (!m_stream.is_open()) return; + + std::stringstream ss; + ss << "[" << verbosity_to_string(msg.verbosity) << "] [" << msg.category->name << "] " << msg.text << "\n"; + std::string str = ss.str(); + + if (m_current_size + str.size() > m_max_file_size) + { + roll_file(); + } + + m_stream << str; + m_current_size += str.size(); + m_stream.flush(); + } + + void RollingFileSink::flush() + { + if (m_stream.is_open()) m_stream.flush(); + } +} diff --git a/Engine/cpp/runtime/core/logging/logging.cppm b/Engine/cpp/runtime/core/logging/logging.cppm new file mode 100644 index 00000000..6bade627 --- /dev/null +++ b/Engine/cpp/runtime/core/logging/logging.cppm @@ -0,0 +1,168 @@ +module; + +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include "macros.h" + +export module core.logging; + +import core.stdtypes; + +export namespace draco::core::logging +{ + inline constexpr usize MaxLogMessageLength = 512; + + enum class LogVerbosity : u8 + { + Fatal, + Error, + Warning, + Display, + Info, + Verbose, + VeryVerbose + }; + + struct LogCategory + { + const char* name; + mutable std::atomic override_verbosity{ -1 }; + }; + + struct LogMessage + { + u64 sequence_id; + u64 uptime_ns; + u32 thread_id; + + LogVerbosity verbosity; + const LogCategory* category; + + const char* file; + const char* function; + u32 line; + + char text[MaxLogMessageLength]; + }; + + struct ILogSink + { + virtual ~ILogSink() = default; + virtual void write(const LogMessage& msg) = 0; + virtual void flush() = 0; + }; + + class ConsoleSink final : public ILogSink + { + public: + void write(const LogMessage& msg) override; + void flush() override; + }; + + class FileSink : public ILogSink + { + protected: + std::ofstream m_stream; + public: + FileSink(const std::filesystem::path& path); + void write(const LogMessage& msg) override; + void flush() override; + }; + + class RollingFileSink final : public ILogSink + { + private: + std::filesystem::path m_base_path; + usize m_max_file_size; + usize m_current_size{0}; + std::ofstream m_stream; + void roll_file(); + public: + RollingFileSink(const std::filesystem::path& base_path, usize max_file_size); + void write(const LogMessage& msg) override; + void flush() override; + }; + + struct LoggerMetrics + { + u64 messages_written; + u64 messages_dropped; + u64 queue_depth; + u32 active_sinks; + u64 uptime_ns; + }; + + namespace internal + { + extern void (*fatal_hook)(); + } + + void init(); + void shutdown(); + void flush(); + + void set_global_verbosity(LogVerbosity verbosity); + + void add_sink(std::shared_ptr sink); + void remove_sink(std::shared_ptr sink); + + void log(LogVerbosity verbosity, const LogCategory& category, const char* file, const char* function, u32 line, const char* text); + + [[noreturn]] void fatal(const LogCategory& category, const char* file, const char* function, u32 line, const char* text); + + LoggerMetrics get_metrics(); + + template + void log_fmt(LogVerbosity verbosity, const LogCategory& category, const char* file, const char* function, u32 line, std::format_string fmt, Args&&... args) + { + char buffer[MaxLogMessageLength]; + bool success = false; + try + { + auto result = std::format_to_n(buffer, MaxLogMessageLength - 1, fmt, std::forward(args)...); + *result.out = '\0'; + success = true; + } + catch (const std::format_error&) + { + // Only catch string formatting failures + } + + if (success) { + log(verbosity, category, file, function, line, buffer); + } else { + log(verbosity, category, file, function, line, ""); + } + } + + template + [[noreturn]] void fatal_fmt(const LogCategory& category, const char* file, const char* function, u32 line, std::format_string fmt, Args&&... args) + { + char buffer[MaxLogMessageLength]; + bool success = false; + try + { + auto result = std::format_to_n(buffer, MaxLogMessageLength - 1, fmt, std::forward(args)...); + *result.out = '\0'; + success = true; + } + catch (const std::format_error&) + { + // Only catch string formatting failures + } + + if (success) { + fatal(category, file, function, line, buffer); + } else { + fatal(category, file, function, line, ""); + } + } +} diff --git a/Engine/cpp/runtime/core/logging/logging.test.cpp b/Engine/cpp/runtime/core/logging/logging.test.cpp new file mode 100644 index 00000000..44cc588f --- /dev/null +++ b/Engine/cpp/runtime/core/logging/logging.test.cpp @@ -0,0 +1,369 @@ +#define DOCTEST_CONFIG_IMPLEMENT_WITH_MAIN +#include + +#include +#include +#include +#include +#include +#include +#include +#include + +#include "macros.h" + +import core.logging; +import core.stdtypes; + +DEFINE_LOG_CATEGORY(Test); +DEFINE_LOG_CATEGORY(Rendering); +DEFINE_LOG_CATEGORY(Physics); + +namespace draco::core::logging +{ + namespace + { + struct TestSink final : ILogSink + { + std::atomic write_count{0}; + std::atomic flush_count{0}; + std::mutex last_mutex; + LogMessage last{}; + draco::u64 expected_seq{0}; + + void write(const LogMessage& msg) override + { + std::lock_guard lock(last_mutex); + last = msg; + write_count.fetch_add(1); + + if (msg.verbosity != LogVerbosity::Fatal) + { + REQUIRE(msg.sequence_id == expected_seq); + expected_seq++; + } + } + + void flush() override + { + flush_count.fetch_add(1); + } + }; + + void wait_for_condition(auto&& fn, int timeout_ms = 2000) + { + using namespace std::chrono; + auto start = steady_clock::now(); + while (!fn()) + { + if (duration_cast(steady_clock::now() - start).count() > timeout_ms) + break; + std::this_thread::sleep_for(std::chrono::milliseconds(1)); + } + } + } +} + +TEST_CASE("Logger init and shutdown do not crash") +{ + using namespace draco::core::logging; + init(); + shutdown(); +} + +TEST_CASE("Logger dispatches messages to sinks (async)") +{ + using namespace draco::core::logging; + init(); + + auto sink = std::make_shared(); + add_sink(sink); + + log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "Hello Logging"); + + wait_for_condition([&] { return sink->write_count.load() >= 1; }); + + REQUIRE(sink->write_count.load() == 1); + REQUIRE(sink->last.category == &LogTest); + REQUIRE(sink->last.verbosity == LogVerbosity::Info); + REQUIRE(std::string_view(sink->last.text) == "Hello Logging"); + + shutdown(); +} + +TEST_CASE("Logger flush calls sink flush and acts as a safe barrier") +{ + using namespace draco::core::logging; + init(); + + auto sink = std::make_shared(); + add_sink(sink); + + log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "Barrier Test"); + flush(); + + REQUIRE(sink->write_count.load() == 1); + REQUIRE(sink->flush_count.load() == 1); + + shutdown(); +} + +TEST_CASE("Logger generates monotonically increasing sequence ids") +{ + using namespace draco::core::logging; + init(); + + auto sink = std::make_shared(); + add_sink(sink); + + log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "A"); + log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "B"); + log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "C"); + + flush(); + + REQUIRE(sink->write_count.load() == 3); + REQUIRE(sink->last.sequence_id == 2); + + shutdown(); +} + +TEST_CASE("Logger respects global verbosity filter") +{ + using namespace draco::core::logging; + init(); + + auto sink = std::make_shared(); + add_sink(sink); + + set_global_verbosity(LogVerbosity::Warning); + + log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "Hidden"); + log(LogVerbosity::Error, LogTest, __FILE__, __func__, __LINE__, "Visible"); + + flush(); + + REQUIRE(sink->write_count.load() == 1); + + shutdown(); +} + +TEST_CASE("Logger handles multiple sinks and removal") +{ + using namespace draco::core::logging; + init(); + + auto a = std::make_shared(); + auto b = std::make_shared(); + + add_sink(a); + add_sink(b); + + log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "Multi Sink"); + flush(); + + REQUIRE(a->write_count.load() == 1); + REQUIRE(b->write_count.load() == 1); + + remove_sink(b); + log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "Only A"); + flush(); + + REQUIRE(a->write_count.load() == 2); + REQUIRE(b->write_count.load() == 1); + + shutdown(); +} + +TEST_CASE("Async System Stress Test - Dropping Allowed") +{ + using namespace draco::core::logging; + init(); + + auto sink = std::make_shared(); + add_sink(sink); + + constexpr int NUM_THREADS = 16; + constexpr int MSG_PER_THREAD = 100000; + + std::vector threads; + threads.reserve(NUM_THREADS); + + for (int i = 0; i < NUM_THREADS; ++i) + { + threads.emplace_back([i]() { + for (int j = 0; j < MSG_PER_THREAD; ++j) + { + log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "Stress Test Message"); + } + }); + } + + for (auto& t : threads) + { + t.join(); + } + + flush(); + + LoggerMetrics m = get_metrics(); + REQUIRE(m.messages_written + m.messages_dropped == NUM_THREADS * MSG_PER_THREAD); + REQUIRE(sink->write_count.load() == m.messages_written); + + shutdown(); +} + +TEST_CASE("Logger handles Queue Overflow gracefully") +{ + using namespace draco::core::logging; + init(); + + auto sink = std::make_shared(); + add_sink(sink); + + for (int i = 0; i < 50000; ++i) + { + log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "Spam"); + } + + flush(); + + LoggerMetrics m = get_metrics(); + REQUIRE(m.messages_written + m.messages_dropped == 50000); + + shutdown(); +} + +struct FatalTestException {}; + +TEST_CASE("Fatal path writes directly and aborts") +{ + using namespace draco::core::logging; + init(); + + auto sink = std::make_shared(); + add_sink(sink); + + draco::core::logging::internal::fatal_hook = [] { throw FatalTestException{}; }; + + bool caught = false; + try + { + LOG_FATAL(Test, "Fatal crash {}!", 123); + } + catch (const FatalTestException&) + { + caught = true; + } + + CHECK(caught); + CHECK(sink->write_count.load() == 1); + CHECK(sink->flush_count.load() == 1); + CHECK(std::string_view(sink->last.text) == "Fatal crash 123!"); + + draco::core::logging::internal::fatal_hook = [] { std::abort(); }; + shutdown(); +} + +TEST_CASE("Logging drops silently after shutdown") +{ + using namespace draco::core::logging; + init(); + + auto sink = std::make_shared(); + add_sink(sink); + + shutdown(); + + log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "Post-shutdown ignored"); + + REQUIRE(sink->write_count.load() == 0); +} + +TEST_CASE("File Sinks Validation") +{ + using namespace draco::core::logging; + init(); + + std::filesystem::path test_path = "test_output.log"; + std::filesystem::remove(test_path); + + { + auto file_sink = std::make_shared(test_path); + add_sink(file_sink); + + log(LogVerbosity::Error, LogTest, __FILE__, __func__, __LINE__, "File Sink Data"); + flush(); + remove_sink(file_sink); + } + + REQUIRE(std::filesystem::exists(test_path)); + std::ifstream infile(test_path); + std::string line; + std::getline(infile, line); + REQUIRE(line.find("File Sink Data") != std::string::npos); + + std::filesystem::remove(test_path); + shutdown(); +} + +TEST_CASE("Formatting and Macro Validation") +{ + using namespace draco::core::logging; + init(); + + auto sink = std::make_shared(); + add_sink(sink); + + LOG_INFO(Test, "Player {} joined", 42); + flush(); + REQUIRE(std::string_view(sink->last.text) == "Player 42 joined"); + + LOG_WARNING(Test, "FPS dropped to {}", 59.5); + flush(); + REQUIRE(std::string_view(sink->last.text) == "FPS dropped to 59.5"); + + shutdown(); +} + +TEST_CASE("Category Overrides Validation") +{ + using namespace draco::core::logging; + init(); + + auto sink = std::make_shared(); + add_sink(sink); + + set_global_verbosity(LogVerbosity::Info); + SET_CATEGORY_VERBOSITY(Rendering, Verbose); + SET_CATEGORY_VERBOSITY(Physics, Error); + + log(LogVerbosity::Verbose, LogRendering, __FILE__, __func__, __LINE__, "Render Pass"); + log(LogVerbosity::Info, LogPhysics, __FILE__, __func__, __LINE__, "Physics Update"); + + flush(); + + REQUIRE(sink->write_count.load() == 1); + REQUIRE(std::string_view(sink->last.text) == "Render Pass"); + + shutdown(); +} + +TEST_CASE("Performance Metrics Operations") +{ + using namespace draco::core::logging; + init(); + + auto sink = std::make_shared(); + add_sink(sink); + + log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "Metrics Check"); + flush(); + + LoggerMetrics m = get_metrics(); + REQUIRE(m.messages_written == 1); + REQUIRE(m.active_sinks == 1); + REQUIRE(m.uptime_ns > 0); + + shutdown(); +} diff --git a/Engine/cpp/runtime/core/logging/macros.h b/Engine/cpp/runtime/core/logging/macros.h new file mode 100644 index 00000000..bc24db63 --- /dev/null +++ b/Engine/cpp/runtime/core/logging/macros.h @@ -0,0 +1,19 @@ +#pragma once + +#include + +#define DECLARE_LOG_CATEGORY(CategoryName) \ + extern const draco::core::logging::LogCategory Log##CategoryName; + +#define DEFINE_LOG_CATEGORY(CategoryName) \ + alignas(draco::core::logging::LogCategory) const draco::core::logging::LogCategory Log##CategoryName { #CategoryName, { -1 } }; + +#define SET_CATEGORY_VERBOSITY(CategoryName, Verbosity) \ + Log##CategoryName.override_verbosity.store(static_cast(draco::core::logging::LogVerbosity::Verbosity), std::memory_order_relaxed); + +#define LOG_FATAL(Category, fmt, ...) draco::core::logging::fatal_fmt(Log##Category, __FILE__, __func__, __LINE__, fmt, ##__VA_ARGS__) +#define LOG_ERROR(Category, fmt, ...) draco::core::logging::log_fmt(draco::core::logging::LogVerbosity::Error, Log##Category, __FILE__, __func__, __LINE__, fmt, ##__VA_ARGS__) +#define LOG_WARNING(Category, fmt, ...) draco::core::logging::log_fmt(draco::core::logging::LogVerbosity::Warning, Log##Category, __FILE__, __func__, __LINE__, fmt, ##__VA_ARGS__) +#define LOG_DISPLAY(Category, fmt, ...) draco::core::logging::log_fmt(draco::core::logging::LogVerbosity::Display, Log##Category, __FILE__, __func__, __LINE__, fmt, ##__VA_ARGS__) +#define LOG_INFO(Category, fmt, ...) draco::core::logging::log_fmt(draco::core::logging::LogVerbosity::Info, Log##Category, __FILE__, __func__, __LINE__, fmt, ##__VA_ARGS__) +#define LOG_VERBOSE(Category, fmt, ...) draco::core::logging::log_fmt(draco::core::logging::LogVerbosity::Verbose, Log##Category, __FILE__, __func__, __LINE__, fmt, ##__VA_ARGS__) From f8bc400a9c3654cf4a392014363b175517e2b433 Mon Sep 17 00:00:00 2001 From: AR-DEV-1 Date: Wed, 17 Jun 2026 21:40:12 +0500 Subject: [PATCH 2/5] Apply suggestions --- Engine/cpp/runtime/core/logging/logging.cpp | 19 ++++++++++++++++--- .../cpp/runtime/core/logging/logging.test.cpp | 9 ++++++++- Engine/cpp/runtime/core/logging/macros.h | 1 + 3 files changed, 25 insertions(+), 4 deletions(-) diff --git a/Engine/cpp/runtime/core/logging/logging.cpp b/Engine/cpp/runtime/core/logging/logging.cpp index 2211e06a..9dc0fe38 100644 --- a/Engine/cpp/runtime/core/logging/logging.cpp +++ b/Engine/cpp/runtime/core/logging/logging.cpp @@ -59,6 +59,8 @@ namespace draco::core::logging static std::atomic> g_sink_list{ nullptr }; static std::mutex g_sink_update_mutex; + static std::mutex g_sink_io_mutex; + static std::atomic g_roll_seq{0}; static std::chrono::steady_clock::time_point g_start_time; @@ -165,7 +167,10 @@ namespace draco::core::logging { for (auto& sink : current_sinks->sinks) { - if (sink) sink->write(msg); + if (sink) { + std::lock_guard io_lock(g_sink_io_mutex); + sink->write(msg); + } } } g_written_count.fetch_add(1, std::memory_order_relaxed); @@ -194,6 +199,10 @@ namespace draco::core::logging void init() { + if (g_worker_thread.joinable()) { + return; + } + g_start_time = std::chrono::steady_clock::now(); g_global_verbosity.store(LogVerbosity::Info); g_dropped_count.store(0); @@ -257,7 +266,10 @@ namespace draco::core::logging { for (auto& sink : current_sinks->sinks) { - if (sink) sink->flush(); + if (sink) { + std::lock_guard io_lock(g_sink_io_mutex); + sink->flush(); + } } } } @@ -365,6 +377,7 @@ namespace draco::core::logging { if (sink) { + std::lock_guard io_lock(g_sink_io_mutex); sink->write(msg); sink->flush(); } @@ -441,7 +454,7 @@ namespace draco::core::logging localtime_r(&time, &tm_buf); #endif std::stringstream ss; - ss << std::put_time(&tm_buf, "%Y%m%d_%H%M%S"); + ss << std::put_time(&tm_buf, "%Y%m%d_%H%M%S") << "_" << g_roll_seq.fetch_add(1, std::memory_order_relaxed); std::string ext = m_base_path.extension().string(); std::string stem = m_base_path.stem().string(); diff --git a/Engine/cpp/runtime/core/logging/logging.test.cpp b/Engine/cpp/runtime/core/logging/logging.test.cpp index 44cc588f..60589095 100644 --- a/Engine/cpp/runtime/core/logging/logging.test.cpp +++ b/Engine/cpp/runtime/core/logging/logging.test.cpp @@ -244,6 +244,14 @@ TEST_CASE("Fatal path writes directly and aborts") auto sink = std::make_shared(); add_sink(sink); + auto previous_fatal_hook = draco::core::logging::internal::fatal_hook; + + struct FatalHookRestore final { + void (**slot)(); + void (*old_value)(); + ~FatalHookRestore() { *slot = old_value; } + } fatal_hook_restore{&draco::core::logging::internal::fatal_hook, previous_fatal_hook}; + draco::core::logging::internal::fatal_hook = [] { throw FatalTestException{}; }; bool caught = false; @@ -261,7 +269,6 @@ TEST_CASE("Fatal path writes directly and aborts") CHECK(sink->flush_count.load() == 1); CHECK(std::string_view(sink->last.text) == "Fatal crash 123!"); - draco::core::logging::internal::fatal_hook = [] { std::abort(); }; shutdown(); } diff --git a/Engine/cpp/runtime/core/logging/macros.h b/Engine/cpp/runtime/core/logging/macros.h index bc24db63..0bb293dc 100644 --- a/Engine/cpp/runtime/core/logging/macros.h +++ b/Engine/cpp/runtime/core/logging/macros.h @@ -1,4 +1,5 @@ #pragma once +#include #include From 4357f3a7171700c0b5010fa1604c6d5bf1f0326e Mon Sep 17 00:00:00 2001 From: AbdulRehman Date: Wed, 17 Jun 2026 21:43:12 +0500 Subject: [PATCH 3/5] Apply suggestions Co-authored-by: coderabbitai[bot] <136622811+coderabbitai[bot]@users.noreply.github.com> --- .../cpp/runtime/core/logging/logging.test.cpp | 19 ++++++++++++------- 1 file changed, 12 insertions(+), 7 deletions(-) diff --git a/Engine/cpp/runtime/core/logging/logging.test.cpp b/Engine/cpp/runtime/core/logging/logging.test.cpp index 60589095..3f73f958 100644 --- a/Engine/cpp/runtime/core/logging/logging.test.cpp +++ b/Engine/cpp/runtime/core/logging/logging.test.cpp @@ -292,8 +292,11 @@ TEST_CASE("File Sinks Validation") using namespace draco::core::logging; init(); - std::filesystem::path test_path = "test_output.log"; - std::filesystem::remove(test_path); + const auto test_path = + std::filesystem::temp_directory_path() / + (std::string("draco_logging_test_") + + std::to_string(std::chrono::steady_clock::now().time_since_epoch().count()) + + ".log"); { auto file_sink = std::make_shared(test_path); @@ -305,12 +308,14 @@ TEST_CASE("File Sinks Validation") } REQUIRE(std::filesystem::exists(test_path)); - std::ifstream infile(test_path); - std::string line; - std::getline(infile, line); - REQUIRE(line.find("File Sink Data") != std::string::npos); + { + std::ifstream infile(test_path); + std::string line; + std::getline(infile, line); + REQUIRE(line.find("File Sink Data") != std::string::npos); + } // closes before deletion - std::filesystem::remove(test_path); + REQUIRE(std::filesystem::remove(test_path)); shutdown(); } From 4c6f4e1d3c94760baf9d5deca443440b8e767775 Mon Sep 17 00:00:00 2001 From: AR-DEV-1 <115883839+Shakai-Dev@users.noreply.github.com> Date: Mon, 22 Jun 2026 18:45:25 +0500 Subject: [PATCH 4/5] Apply suggestions --- Docs/LoggingSinks.md | 20 ++ Engine/cpp/runtime/core/logging/logging.cpp | 198 ++++++++++-------- Engine/cpp/runtime/core/logging/logging.cppm | 102 ++++----- .../cpp/runtime/core/logging/logging.test.cpp | 69 +++--- Engine/cpp/runtime/core/logging/macros.h | 20 -- 5 files changed, 198 insertions(+), 211 deletions(-) create mode 100644 Docs/LoggingSinks.md delete mode 100644 Engine/cpp/runtime/core/logging/macros.h diff --git a/Docs/LoggingSinks.md b/Docs/LoggingSinks.md new file mode 100644 index 00000000..b2692c64 --- /dev/null +++ b/Docs/LoggingSinks.md @@ -0,0 +1,20 @@ +# DraconicEngine Logging Sinks + +The logging module in DraconicEngine utilizes an asynchronous sink architecture. Sinks are responsible for formatting and routing `LogMessage` structs to their final destination. + +Currently, the engine provides three native sinks, all implementing the `ILogSink` interface: + +## 1. `ConsoleSink` +Outputs standard formatted logs directly to `stdout`. +* **Usage:** Best for local debugging and immediate developer feedback inside IDE terminals. +* **Performance:** Uses high-speed async queuing, but `stdout` blocking can occur depending on the OS terminal implementation. + +## 2. `FileSink` +Appends incoming log messages to a specified flat file path. +* **Usage:** Standard, long-running application logs where size constraints aren't an immediate concern. +* **Internal:** Implemented using the PIMPL idiom to avoid leaking `` into the module interface. + +## 3. `RollingFileSink` +Behaves like `FileSink`, but intelligently rolls the log to a new file when a predefined size limit (`m_max_file_size`) is hit. +* **Usage:** Production builds and dedicated servers where you need to prevent log files from infinitely ballooning and consuming disk space. +* **Formatting:** Appends a timestamp (`%Y%m%d_%H%M%S`) and an atomic sequence number to the new filename. diff --git a/Engine/cpp/runtime/core/logging/logging.cpp b/Engine/cpp/runtime/core/logging/logging.cpp index 9dc0fe38..90771156 100644 --- a/Engine/cpp/runtime/core/logging/logging.cpp +++ b/Engine/cpp/runtime/core/logging/logging.cpp @@ -16,8 +16,7 @@ module; #include #include #include - -#include "macros.h" +#include module core.logging; @@ -314,78 +313,78 @@ namespace draco::core::logging g_sink_list.store(next, std::memory_order_release); } - void log(LogVerbosity verbosity, const LogCategory& category, const char* file, const char* function, u32 line, const char* text) + namespace internal { - if (!g_accepting_logs.load(std::memory_order_acquire)) return; - - g_active_producers.fetch_add(1, std::memory_order_acquire); - if (!g_accepting_logs.load(std::memory_order_acquire)) + void enqueue_log(LogVerbosity verbosity, const LogCategory& category, const std::source_location& loc, std::string_view text) noexcept { - g_active_producers.fetch_sub(1, std::memory_order_release); - return; - } + if (!g_accepting_logs.load(std::memory_order_acquire)) return; + + g_active_producers.fetch_add(1, std::memory_order_acquire); + if (!g_accepting_logs.load(std::memory_order_acquire)) + { + g_active_producers.fetch_sub(1, std::memory_order_release); + return; + } - LogVerbosity target_verbosity = g_global_verbosity.load(std::memory_order_relaxed); - i32 category_override = category.override_verbosity.load(std::memory_order_relaxed); - if (category_override >= 0) - { - target_verbosity = static_cast(category_override); + LogVerbosity target_verbosity = g_global_verbosity.load(std::memory_order_relaxed); + i32 category_override = category.override_verbosity.load(std::memory_order_relaxed); + if (category_override >= 0) + { + target_verbosity = static_cast(category_override); + } + + if (verbosity <= target_verbosity) + { + LogMessage msg{}; + msg.uptime_ns = uptime_ns(); + msg.thread_id = get_thread_id(); + msg.verbosity = verbosity; + msg.category = &category; + msg.location = loc; + + const usize len = std::min(text.size(), MaxLogMessageLength - 1); + std::memcpy(msg.text, text.data(), len); + msg.text[len] = '\0'; + + enqueue(msg); + } + + g_active_producers.fetch_sub(1, std::memory_order_release); } - if (verbosity <= target_verbosity) + [[noreturn]] void execute_fatal(const LogCategory& category, const std::source_location& loc, std::string_view text) { LogMessage msg{}; msg.uptime_ns = uptime_ns(); msg.thread_id = get_thread_id(); - msg.verbosity = verbosity; + msg.verbosity = LogVerbosity::Fatal; msg.category = &category; - msg.file = file; - msg.function = function; - msg.line = line; - - std::strncpy(msg.text, text, MaxLogMessageLength - 1); - msg.text[MaxLogMessageLength - 1] = '\0'; - - enqueue(msg); - } - - g_active_producers.fetch_sub(1, std::memory_order_release); - } + msg.location = loc; - [[noreturn]] - void fatal(const LogCategory& category, const char* file, const char* function, u32 line, const char* text) - { - LogMessage msg{}; - msg.uptime_ns = uptime_ns(); - msg.thread_id = get_thread_id(); - msg.verbosity = LogVerbosity::Fatal; - msg.category = &category; - msg.file = file; - msg.function = function; - msg.line = line; - - std::strncpy(msg.text, text, MaxLogMessageLength - 1); - msg.text[MaxLogMessageLength - 1] = '\0'; + const usize len = std::min(text.size(), MaxLogMessageLength - 1); + std::memcpy(msg.text, text.data(), len); + msg.text[len] = '\0'; - f64 uptime_s = static_cast(msg.uptime_ns) / 1'000'000'000.0; - std::println("[FATAL] [{:.6f}] [{}]: {}", uptime_s, category.name, msg.text); + f64 uptime_s = static_cast(msg.uptime_ns) / 1'000'000'000.0; + std::println("[FATAL] [{:.6f}] [{}]: {}", uptime_s, category.name, msg.text); - std::shared_ptr current_sinks = g_sink_list.load(std::memory_order_acquire); - if (current_sinks) - { - for (auto& sink : current_sinks->sinks) + std::shared_ptr current_sinks = g_sink_list.load(std::memory_order_acquire); + if (current_sinks) { - if (sink) + for (auto& sink : current_sinks->sinks) { - std::lock_guard io_lock(g_sink_io_mutex); - sink->write(msg); - sink->flush(); + if (sink) + { + std::lock_guard io_lock(g_sink_io_mutex); + sink->write(msg); + sink->flush(); + } } } - } - internal::fatal_hook(); - std::abort(); + internal::fatal_hook(); + std::abort(); + } } LoggerMetrics get_metrics() @@ -415,76 +414,91 @@ namespace draco::core::logging std::fflush(stdout); } - FileSink::FileSink(const std::filesystem::path& path) + struct FileSink::Impl { + std::ofstream stream; + }; + + FileSink::FileSink(const std::filesystem::path& path) : m_impl(std::make_unique()) { - m_stream.open(path, std::ios::out | std::ios::app); + m_impl->stream.open(path, std::ios::out | std::ios::app); } + FileSink::~FileSink() = default; + void FileSink::write(const LogMessage& msg) { - if (m_stream.is_open()) + if (m_impl->stream.is_open()) { - m_stream << "[" << verbosity_to_string(msg.verbosity) << "] [" << msg.category->name << "] " << msg.text << "\n"; + m_impl->stream << "[" << verbosity_to_string(msg.verbosity) << "] [" << msg.category->name << "] " << msg.text << "\n"; } } void FileSink::flush() { - if (m_stream.is_open()) - { - m_stream.flush(); - } + if (m_impl->stream.is_open()) m_impl->stream.flush(); } - RollingFileSink::RollingFileSink(const std::filesystem::path& base_path, usize max_file_size) : m_base_path(base_path), m_max_file_size(max_file_size) - { - roll_file(); - } + struct RollingFileSink::Impl { + std::filesystem::path base_path; + usize max_file_size; + usize current_size{0}; + std::ofstream stream; - void RollingFileSink::roll_file() - { - if (m_stream.is_open()) m_stream.close(); + void roll_file() { + if (stream.is_open()) + stream.close(); + + auto now = std::chrono::system_clock::now(); + auto time = std::chrono::system_clock::to_time_t(now); + std::tm tm_buf{}; - auto now = std::chrono::system_clock::now(); - auto time = std::chrono::system_clock::to_time_t(now); - std::tm tm_buf{}; #if defined(_WIN32) - localtime_s(&tm_buf, &time); + localtime_s(&tm_buf, &time); #else - localtime_r(&time, &tm_buf); + localtime_r(&time, &tm_buf); #endif - std::stringstream ss; - ss << std::put_time(&tm_buf, "%Y%m%d_%H%M%S") << "_" << g_roll_seq.fetch_add(1, std::memory_order_relaxed); - - std::string ext = m_base_path.extension().string(); - std::string stem = m_base_path.stem().string(); - auto parent = m_base_path.parent_path(); + std::stringstream ss; + ss << std::put_time(&tm_buf, "%Y%m%d_%H%M%S") << "_" << g_roll_seq.fetch_add(1, std::memory_order_relaxed); + + std::string ext = base_path.extension().string(); + std::string stem = base_path.stem().string(); + auto parent = base_path.parent_path(); + + std::filesystem::path new_path = parent / (stem + "_" + ss.str() + ext); + stream.open(new_path, std::ios::out | std::ios::trunc); + current_size = 0; + } + }; - std::filesystem::path new_path = parent / (stem + "_" + ss.str() + ext); - m_stream.open(new_path, std::ios::out | std::ios::trunc); - m_current_size = 0; + RollingFileSink::RollingFileSink(const std::filesystem::path& base_path, usize max_file_size) : m_impl(std::make_unique()) + { + m_impl->base_path = base_path; + m_impl->max_file_size = max_file_size; + m_impl->roll_file(); } + RollingFileSink::~RollingFileSink() = default; void RollingFileSink::write(const LogMessage& msg) { - if (!m_stream.is_open()) return; + if (!m_impl->stream.is_open()) + return; std::stringstream ss; ss << "[" << verbosity_to_string(msg.verbosity) << "] [" << msg.category->name << "] " << msg.text << "\n"; std::string str = ss.str(); - if (m_current_size + str.size() > m_max_file_size) + if (m_impl->current_size + str.size() > m_impl->max_file_size) { - roll_file(); + m_impl->roll_file(); } - m_stream << str; - m_current_size += str.size(); - m_stream.flush(); + m_impl->stream << str; + m_impl->current_size += str.size(); + m_impl->stream.flush(); } void RollingFileSink::flush() { - if (m_stream.is_open()) m_stream.flush(); + if (m_impl->stream.is_open()) m_impl->stream.flush(); } } diff --git a/Engine/cpp/runtime/core/logging/logging.cppm b/Engine/cpp/runtime/core/logging/logging.cppm index 6bade627..d96bb049 100644 --- a/Engine/cpp/runtime/core/logging/logging.cppm +++ b/Engine/cpp/runtime/core/logging/logging.cppm @@ -1,16 +1,14 @@ module; #include -#include -#include -#include -#include +#include #include +#include +#include #include -#include -#include - -#include "macros.h" +#include +#include +#include export module core.logging; @@ -45,10 +43,8 @@ export namespace draco::core::logging LogVerbosity verbosity; const LogCategory* category; - - const char* file; - const char* function; - u32 line; + + std::source_location location; char text[MaxLogMessageLength]; }; @@ -67,12 +63,15 @@ export namespace draco::core::logging void flush() override; }; - class FileSink : public ILogSink + class FileSink final : public ILogSink { - protected: - std::ofstream m_stream; + private: + struct Impl; + std::unique_ptr m_impl; public: FileSink(const std::filesystem::path& path); + ~FileSink() override; + void write(const LogMessage& msg) override; void flush() override; }; @@ -80,13 +79,12 @@ export namespace draco::core::logging class RollingFileSink final : public ILogSink { private: - std::filesystem::path m_base_path; - usize m_max_file_size; - usize m_current_size{0}; - std::ofstream m_stream; - void roll_file(); + struct Impl; + std::unique_ptr m_impl; public: RollingFileSink(const std::filesystem::path& base_path, usize max_file_size); + ~RollingFileSink() override; + void write(const LogMessage& msg) override; void flush() override; }; @@ -103,66 +101,48 @@ export namespace draco::core::logging namespace internal { extern void (*fatal_hook)(); + void enqueue_log(LogVerbosity verbosity, const LogCategory& category, const std::source_location& loc, std::string_view text) noexcept; + [[noreturn]] void execute_fatal(const LogCategory& category, const std::source_location& loc, std::string_view text); } void init(); void shutdown(); void flush(); - + void set_global_verbosity(LogVerbosity verbosity); void add_sink(std::shared_ptr sink); void remove_sink(std::shared_ptr sink); - void log(LogVerbosity verbosity, const LogCategory& category, const char* file, const char* function, u32 line, const char* text); - - [[noreturn]] void fatal(const LogCategory& category, const char* file, const char* function, u32 line, const char* text); - LoggerMetrics get_metrics(); + template + struct LogFormatString + { + std::format_string fmt; + std::source_location loc; + + template + requires std::constructible_from, T> + consteval LogFormatString(const T& s, std::source_location l = std::source_location::current()) + : fmt(s), loc(l) {} + }; + template - void log_fmt(LogVerbosity verbosity, const LogCategory& category, const char* file, const char* function, u32 line, std::format_string fmt, Args&&... args) + void log(LogVerbosity verbosity, const LogCategory& category, LogFormatString...> fmt, Args&&... args) noexcept { char buffer[MaxLogMessageLength]; - bool success = false; - try - { - auto result = std::format_to_n(buffer, MaxLogMessageLength - 1, fmt, std::forward(args)...); - *result.out = '\0'; - success = true; - } - catch (const std::format_error&) - { - // Only catch string formatting failures - } - - if (success) { - log(verbosity, category, file, function, line, buffer); - } else { - log(verbosity, category, file, function, line, ""); - } + auto result = std::format_to_n(buffer, MaxLogMessageLength - 1, fmt.fmt, std::forward(args)...); + *result.out = '\0'; + internal::enqueue_log(verbosity, category, fmt.loc, buffer); } template - [[noreturn]] void fatal_fmt(const LogCategory& category, const char* file, const char* function, u32 line, std::format_string fmt, Args&&... args) + [[noreturn]] void fatal(const LogCategory& category, LogFormatString...> fmt, Args&&... args) { char buffer[MaxLogMessageLength]; - bool success = false; - try - { - auto result = std::format_to_n(buffer, MaxLogMessageLength - 1, fmt, std::forward(args)...); - *result.out = '\0'; - success = true; - } - catch (const std::format_error&) - { - // Only catch string formatting failures - } - - if (success) { - fatal(category, file, function, line, buffer); - } else { - fatal(category, file, function, line, ""); - } + auto result = std::format_to_n(buffer, MaxLogMessageLength - 1, fmt.fmt, std::forward(args)...); + *result.out = '\0'; + internal::execute_fatal(category, fmt.loc, buffer); } } diff --git a/Engine/cpp/runtime/core/logging/logging.test.cpp b/Engine/cpp/runtime/core/logging/logging.test.cpp index 3f73f958..021b3788 100644 --- a/Engine/cpp/runtime/core/logging/logging.test.cpp +++ b/Engine/cpp/runtime/core/logging/logging.test.cpp @@ -10,14 +10,12 @@ #include #include -#include "macros.h" - import core.logging; import core.stdtypes; -DEFINE_LOG_CATEGORY(Test); -DEFINE_LOG_CATEGORY(Rendering); -DEFINE_LOG_CATEGORY(Physics); +inline const draco::core::logging::LogCategory LogTest{"Test"}; +inline const draco::core::logging::LogCategory LogRendering{"Rendering"}; +inline const draco::core::logging::LogCategory LogPhysics{"Physics"}; namespace draco::core::logging { @@ -79,7 +77,7 @@ TEST_CASE("Logger dispatches messages to sinks (async)") auto sink = std::make_shared(); add_sink(sink); - log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "Hello Logging"); + log(LogVerbosity::Info, LogTest, "Hello Logging"); wait_for_condition([&] { return sink->write_count.load() >= 1; }); @@ -99,7 +97,7 @@ TEST_CASE("Logger flush calls sink flush and acts as a safe barrier") auto sink = std::make_shared(); add_sink(sink); - log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "Barrier Test"); + log(LogVerbosity::Info, LogTest, "Barrier Test"); flush(); REQUIRE(sink->write_count.load() == 1); @@ -116,9 +114,9 @@ TEST_CASE("Logger generates monotonically increasing sequence ids") auto sink = std::make_shared(); add_sink(sink); - log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "A"); - log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "B"); - log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "C"); + log(LogVerbosity::Info, LogTest, "A"); + log(LogVerbosity::Info, LogTest, "B"); + log(LogVerbosity::Info, LogTest, "C"); flush(); @@ -138,8 +136,8 @@ TEST_CASE("Logger respects global verbosity filter") set_global_verbosity(LogVerbosity::Warning); - log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "Hidden"); - log(LogVerbosity::Error, LogTest, __FILE__, __func__, __LINE__, "Visible"); + log(LogVerbosity::Info, LogTest, "Hidden"); + log(LogVerbosity::Error, LogTest, "Visible"); flush(); @@ -159,14 +157,14 @@ TEST_CASE("Logger handles multiple sinks and removal") add_sink(a); add_sink(b); - log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "Multi Sink"); + log(LogVerbosity::Info, LogTest, "Multi Sink"); flush(); REQUIRE(a->write_count.load() == 1); REQUIRE(b->write_count.load() == 1); remove_sink(b); - log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "Only A"); + log(LogVerbosity::Info, LogTest, "Only A"); flush(); REQUIRE(a->write_count.load() == 2); @@ -194,7 +192,7 @@ TEST_CASE("Async System Stress Test - Dropping Allowed") threads.emplace_back([i]() { for (int j = 0; j < MSG_PER_THREAD; ++j) { - log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "Stress Test Message"); + log(LogVerbosity::Info, LogTest, "Stress Test Message"); } }); } @@ -223,7 +221,7 @@ TEST_CASE("Logger handles Queue Overflow gracefully") for (int i = 0; i < 50000; ++i) { - log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "Spam"); + log(LogVerbosity::Info, LogTest, "Spam"); } flush(); @@ -257,7 +255,7 @@ TEST_CASE("Fatal path writes directly and aborts") bool caught = false; try { - LOG_FATAL(Test, "Fatal crash {}!", 123); + fatal(LogTest, "Fatal crash {}!", 123); } catch (const FatalTestException&) { @@ -282,7 +280,7 @@ TEST_CASE("Logging drops silently after shutdown") shutdown(); - log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "Post-shutdown ignored"); + log(LogVerbosity::Info, LogTest, "Post-shutdown ignored"); REQUIRE(sink->write_count.load() == 0); } @@ -292,30 +290,25 @@ TEST_CASE("File Sinks Validation") using namespace draco::core::logging; init(); - const auto test_path = - std::filesystem::temp_directory_path() / - (std::string("draco_logging_test_") + - std::to_string(std::chrono::steady_clock::now().time_since_epoch().count()) + - ".log"); + std::filesystem::path test_path = "test_output.log"; + std::filesystem::remove(test_path); { auto file_sink = std::make_shared(test_path); add_sink(file_sink); - log(LogVerbosity::Error, LogTest, __FILE__, __func__, __LINE__, "File Sink Data"); + log(LogVerbosity::Error, LogTest, "File Sink Data"); flush(); remove_sink(file_sink); } REQUIRE(std::filesystem::exists(test_path)); - { - std::ifstream infile(test_path); - std::string line; - std::getline(infile, line); - REQUIRE(line.find("File Sink Data") != std::string::npos); - } // closes before deletion + std::ifstream infile(test_path); + std::string line; + std::getline(infile, line); + REQUIRE(line.find("File Sink Data") != std::string::npos); - REQUIRE(std::filesystem::remove(test_path)); + std::filesystem::remove(test_path); shutdown(); } @@ -327,11 +320,11 @@ TEST_CASE("Formatting and Macro Validation") auto sink = std::make_shared(); add_sink(sink); - LOG_INFO(Test, "Player {} joined", 42); + log(LogVerbosity::Info, LogTest, "Player {} joined", 42); flush(); REQUIRE(std::string_view(sink->last.text) == "Player 42 joined"); - LOG_WARNING(Test, "FPS dropped to {}", 59.5); + log(LogVerbosity::Warning, LogTest, "FPS dropped to {}", 59.5); flush(); REQUIRE(std::string_view(sink->last.text) == "FPS dropped to 59.5"); @@ -347,11 +340,11 @@ TEST_CASE("Category Overrides Validation") add_sink(sink); set_global_verbosity(LogVerbosity::Info); - SET_CATEGORY_VERBOSITY(Rendering, Verbose); - SET_CATEGORY_VERBOSITY(Physics, Error); + LogRendering.override_verbosity.store(static_cast(LogVerbosity::Verbose), std::memory_order_relaxed); + LogPhysics.override_verbosity.store(static_cast(LogVerbosity::Error), std::memory_order_relaxed); - log(LogVerbosity::Verbose, LogRendering, __FILE__, __func__, __LINE__, "Render Pass"); - log(LogVerbosity::Info, LogPhysics, __FILE__, __func__, __LINE__, "Physics Update"); + log(LogVerbosity::Verbose, LogRendering, "Render Pass"); + log(LogVerbosity::Info, LogPhysics, "Physics Update"); flush(); @@ -369,7 +362,7 @@ TEST_CASE("Performance Metrics Operations") auto sink = std::make_shared(); add_sink(sink); - log(LogVerbosity::Info, LogTest, __FILE__, __func__, __LINE__, "Metrics Check"); + log(LogVerbosity::Info, LogTest, "Metrics Check"); flush(); LoggerMetrics m = get_metrics(); diff --git a/Engine/cpp/runtime/core/logging/macros.h b/Engine/cpp/runtime/core/logging/macros.h deleted file mode 100644 index 0bb293dc..00000000 --- a/Engine/cpp/runtime/core/logging/macros.h +++ /dev/null @@ -1,20 +0,0 @@ -#pragma once -#include - -#include - -#define DECLARE_LOG_CATEGORY(CategoryName) \ - extern const draco::core::logging::LogCategory Log##CategoryName; - -#define DEFINE_LOG_CATEGORY(CategoryName) \ - alignas(draco::core::logging::LogCategory) const draco::core::logging::LogCategory Log##CategoryName { #CategoryName, { -1 } }; - -#define SET_CATEGORY_VERBOSITY(CategoryName, Verbosity) \ - Log##CategoryName.override_verbosity.store(static_cast(draco::core::logging::LogVerbosity::Verbosity), std::memory_order_relaxed); - -#define LOG_FATAL(Category, fmt, ...) draco::core::logging::fatal_fmt(Log##Category, __FILE__, __func__, __LINE__, fmt, ##__VA_ARGS__) -#define LOG_ERROR(Category, fmt, ...) draco::core::logging::log_fmt(draco::core::logging::LogVerbosity::Error, Log##Category, __FILE__, __func__, __LINE__, fmt, ##__VA_ARGS__) -#define LOG_WARNING(Category, fmt, ...) draco::core::logging::log_fmt(draco::core::logging::LogVerbosity::Warning, Log##Category, __FILE__, __func__, __LINE__, fmt, ##__VA_ARGS__) -#define LOG_DISPLAY(Category, fmt, ...) draco::core::logging::log_fmt(draco::core::logging::LogVerbosity::Display, Log##Category, __FILE__, __func__, __LINE__, fmt, ##__VA_ARGS__) -#define LOG_INFO(Category, fmt, ...) draco::core::logging::log_fmt(draco::core::logging::LogVerbosity::Info, Log##Category, __FILE__, __func__, __LINE__, fmt, ##__VA_ARGS__) -#define LOG_VERBOSE(Category, fmt, ...) draco::core::logging::log_fmt(draco::core::logging::LogVerbosity::Verbose, Log##Category, __FILE__, __func__, __LINE__, fmt, ##__VA_ARGS__) From b87c6f4f229bc6766094019c17f01f2e0f29d268 Mon Sep 17 00:00:00 2001 From: AR-DEV-1 <115883839+Shakai-Dev@users.noreply.github.com> Date: Tue, 30 Jun 2026 19:51:01 +0500 Subject: [PATCH 5/5] Apply suggestions (experimental) --- Engine/cpp/runtime/core/logging/logging.cpp | 78 +++++++++++++++---- Engine/cpp/runtime/core/logging/logging.cppm | 16 +++- .../cpp/runtime/core/logging/logging.test.cpp | 2 +- 3 files changed, 76 insertions(+), 20 deletions(-) diff --git a/Engine/cpp/runtime/core/logging/logging.cpp b/Engine/cpp/runtime/core/logging/logging.cpp index 90771156..17d61347 100644 --- a/Engine/cpp/runtime/core/logging/logging.cpp +++ b/Engine/cpp/runtime/core/logging/logging.cpp @@ -2,6 +2,7 @@ module; #include #include +#include #include #include #include @@ -17,6 +18,7 @@ module; #include #include #include +#include module core.logging; @@ -70,7 +72,8 @@ namespace draco::core::logging static u32 get_thread_id() { - return static_cast(std::hash{}(std::this_thread::get_id())); + thread_local u32 cached_id = static_cast(std::hash{}(std::this_thread::get_id())); + return cached_id; } static u64 uptime_ns() @@ -188,8 +191,10 @@ namespace draco::core::logging if (!popped) { std::unique_lock lock(g_worker_mutex); - if (!g_running.load(std::memory_order_acquire)) continue; - if (g_dequeue_pos.load(std::memory_order_relaxed) != g_enqueue_pos.load(std::memory_order_acquire)) continue; + if (!g_running.load(std::memory_order_acquire)) + continue; + if (g_dequeue_pos.load(std::memory_order_relaxed) != g_enqueue_pos.load(std::memory_order_acquire)) + continue; g_worker_cv.wait_for(lock, std::chrono::milliseconds(2)); } @@ -315,6 +320,17 @@ namespace draco::core::logging namespace internal { + bool is_verbosity_enabled(LogVerbosity verbosity, const LogCategory& category) noexcept + { + LogVerbosity target_verbosity = g_global_verbosity.load(std::memory_order_relaxed); + i32 category_override = category.override_verbosity.load(std::memory_order_relaxed); + if (category_override >= 0) + { + target_verbosity = static_cast(category_override); + } + return verbosity <= target_verbosity; + } + void enqueue_log(LogVerbosity verbosity, const LogCategory& category, const std::source_location& loc, std::string_view text) noexcept { if (!g_accepting_logs.load(std::memory_order_acquire)) return; @@ -326,14 +342,7 @@ namespace draco::core::logging return; } - LogVerbosity target_verbosity = g_global_verbosity.load(std::memory_order_relaxed); - i32 category_override = category.override_verbosity.load(std::memory_order_relaxed); - if (category_override >= 0) - { - target_verbosity = static_cast(category_override); - } - - if (verbosity <= target_verbosity) + if (is_verbosity_enabled(verbosity, category)) { LogMessage msg{}; msg.uptime_ns = uptime_ns(); @@ -354,6 +363,8 @@ namespace draco::core::logging [[noreturn]] void execute_fatal(const LogCategory& category, const std::source_location& loc, std::string_view text) { + draco::core::logging::flush(); + LogMessage msg{}; msg.uptime_ns = uptime_ns(); msg.thread_id = get_thread_id(); @@ -366,7 +377,12 @@ namespace draco::core::logging msg.text[len] = '\0'; f64 uptime_s = static_cast(msg.uptime_ns) / 1'000'000'000.0; - std::println("[FATAL] [{:.6f}] [{}]: {}", uptime_s, category.name, msg.text); + std::string_view filename = msg.location.file_name(); + auto last_slash = filename.find_last_of("/\\"); + if (last_slash != std::string_view::npos) + filename = filename.substr(last_slash + 1); + + std::println("[FATAL] [{:.6f}] [{}] [Thread {}] [{}:{}] {}", uptime_s, category.name, msg.thread_id, filename, msg.location.line(), msg.text); std::shared_ptr current_sinks = g_sink_list.load(std::memory_order_acquire); if (current_sinks) @@ -406,7 +422,12 @@ namespace draco::core::logging void ConsoleSink::write(const LogMessage& msg) { f64 uptime_s = static_cast(msg.uptime_ns) / 1'000'000'000.0; - std::println("[{}] [{:.6f}] [{}] {}", verbosity_to_string(msg.verbosity), uptime_s, msg.category->name, msg.text); + std::string_view filename = msg.location.file_name(); + auto last_slash = filename.find_last_of("/\\"); + if (last_slash != std::string_view::npos) + filename = filename.substr(last_slash + 1); + + std::println("[{}] [{:.6f}] [{}] [Thread {}] [{}:{}] {}", verbosity_to_string(msg.verbosity), uptime_s, msg.category->name, msg.thread_id, filename, msg.location.line(), msg.text); } void ConsoleSink::flush() @@ -420,6 +441,11 @@ namespace draco::core::logging FileSink::FileSink(const std::filesystem::path& path) : m_impl(std::make_unique()) { + std::error_code ec; + if (path.has_parent_path() && !std::filesystem::exists(path.parent_path(), ec)) + { + std::filesystem::create_directories(path.parent_path(), ec); + } m_impl->stream.open(path, std::ios::out | std::ios::app); } @@ -429,7 +455,12 @@ namespace draco::core::logging { if (m_impl->stream.is_open()) { - m_impl->stream << "[" << verbosity_to_string(msg.verbosity) << "] [" << msg.category->name << "] " << msg.text << "\n"; + std::string_view filename = msg.location.file_name(); + auto last_slash = filename.find_last_of("/\\"); + if (last_slash != std::string_view::npos) + filename = filename.substr(last_slash + 1); + + m_impl->stream << "[" << verbosity_to_string(msg.verbosity) << "] [" << msg.category->name << "] [Thread " << msg.thread_id << "] [" << filename << ":" << msg.location.line() << "] " << msg.text << "\n"; } } @@ -465,6 +496,13 @@ namespace draco::core::logging auto parent = base_path.parent_path(); std::filesystem::path new_path = parent / (stem + "_" + ss.str() + ext); + + std::error_code ec; + if (new_path.has_parent_path() && !std::filesystem::exists(new_path.parent_path(), ec)) + { + std::filesystem::create_directories(new_path.parent_path(), ec); + } + stream.open(new_path, std::ios::out | std::ios::trunc); current_size = 0; } @@ -476,6 +514,7 @@ namespace draco::core::logging m_impl->max_file_size = max_file_size; m_impl->roll_file(); } + RollingFileSink::~RollingFileSink() = default; void RollingFileSink::write(const LogMessage& msg) @@ -483,8 +522,13 @@ namespace draco::core::logging if (!m_impl->stream.is_open()) return; + std::string_view filename = msg.location.file_name(); + auto last_slash = filename.find_last_of("/\\"); + if (last_slash != std::string_view::npos) + filename = filename.substr(last_slash + 1); + std::stringstream ss; - ss << "[" << verbosity_to_string(msg.verbosity) << "] [" << msg.category->name << "] " << msg.text << "\n"; + ss << "[" << verbosity_to_string(msg.verbosity) << "] [" << msg.category->name << "] [Thread " << msg.thread_id << "] [" << filename << ":" << msg.location.line() << "] " << msg.text << "\n"; std::string str = ss.str(); if (m_impl->current_size + str.size() > m_impl->max_file_size) @@ -494,11 +538,11 @@ namespace draco::core::logging m_impl->stream << str; m_impl->current_size += str.size(); - m_impl->stream.flush(); } void RollingFileSink::flush() { - if (m_impl->stream.is_open()) m_impl->stream.flush(); + if (m_impl->stream.is_open()) + m_impl->stream.flush(); } } diff --git a/Engine/cpp/runtime/core/logging/logging.cppm b/Engine/cpp/runtime/core/logging/logging.cppm index d96bb049..54ec6e44 100644 --- a/Engine/cpp/runtime/core/logging/logging.cppm +++ b/Engine/cpp/runtime/core/logging/logging.cppm @@ -29,6 +29,8 @@ export namespace draco::core::logging VeryVerbose }; + inline constexpr LogVerbosity CompileTimeVerbosityLimit = LogVerbosity::VeryVerbose; + struct LogCategory { const char* name; @@ -101,6 +103,7 @@ export namespace draco::core::logging namespace internal { extern void (*fatal_hook)(); + bool is_verbosity_enabled(LogVerbosity verbosity, const LogCategory& category) noexcept; void enqueue_log(LogVerbosity verbosity, const LogCategory& category, const std::source_location& loc, std::string_view text) noexcept; [[noreturn]] void execute_fatal(const LogCategory& category, const std::source_location& loc, std::string_view text); } @@ -124,13 +127,22 @@ export namespace draco::core::logging template requires std::constructible_from, T> - consteval LogFormatString(const T& s, std::source_location l = std::source_location::current()) - : fmt(s), loc(l) {} + + consteval LogFormatString(const T& s, std::source_location l = std::source_location::current()) : fmt(s), loc(l) {} }; template void log(LogVerbosity verbosity, const LogCategory& category, LogFormatString...> fmt, Args&&... args) noexcept { + if constexpr (CompileTimeVerbosityLimit < LogVerbosity::VeryVerbose) + { + if (verbosity > CompileTimeVerbosityLimit) + return; + } + + if (!internal::is_verbosity_enabled(verbosity, category)) + return; + char buffer[MaxLogMessageLength]; auto result = std::format_to_n(buffer, MaxLogMessageLength - 1, fmt.fmt, std::forward(args)...); *result.out = '\0'; diff --git a/Engine/cpp/runtime/core/logging/logging.test.cpp b/Engine/cpp/runtime/core/logging/logging.test.cpp index 021b3788..fe447fff 100644 --- a/Engine/cpp/runtime/core/logging/logging.test.cpp +++ b/Engine/cpp/runtime/core/logging/logging.test.cpp @@ -264,7 +264,7 @@ TEST_CASE("Fatal path writes directly and aborts") CHECK(caught); CHECK(sink->write_count.load() == 1); - CHECK(sink->flush_count.load() == 1); + CHECK(sink->flush_count.load() == 2); CHECK(std::string_view(sink->last.text) == "Fatal crash 123!"); shutdown();